ndb_unittest_errors.py

from google.appengine.ext import testbed
from google.appengine.ext import ndb  # SDK 1.7, OS X

import unittest
from webtest import TestApp

from main import app

from models import compute_hash #, Subscription

import logging

#
# using this imported from models causes the 
# "Expected Key('Subscription', 123), got Key('Subscription', 123)" error
#
class Subscription(ndb.Model):
    """Subscription to a feed."""
    name = ndb.StringProperty()
    feed_url = ndb.TextProperty()
    last_updated = ndb.DateTimeProperty()
    etag = ndb.StringProperty()
    subscribed = ndb.BooleanProperty(default=True)
    categories = ndb.StringProperty(repeated=True)
    # Support for custom feeds that don't conform to RSS/Atom (AP)
    type = ndb.StringProperty()
    # For feeds that require basic authentication (AP)
    username = ndb.StringProperty()
    password = ndb.StringProperty()

    # Pubsub-specific properties
    is_pubsub = ndb.BooleanProperty(default=False)
    # Does the feed have full-text articles (as opposed to excerpts)?
    full_text = ndb.BooleanProperty(default=False)
    # When feed was confirmed to be valid (for pubsub)
    confirmed_time = ndb.DateTimeProperty()


class TestbedTest(unittest.TestCase):
    def setUp(self):
        self.testbed = testbed.Testbed()
        self.testbed.activate()

        self.testbed.init_datastore_v3_stub()
        self.testbed.init_memcache_stub()

        self.ctx = ndb.tasklets.make_default_context()
        ndb.tasklets.set_context(self.ctx)

        self.testapp = TestApp(app)
    common = setUp

    def tearDown(self):
        self.testbed.deactivate()


class TestDbPutCase(TestbedTest):
    def setUp(self):
        self.common()

    def test_db_put(self):
        # If I import models.Subscription, this causes the traceback (included)
        instance = Subscription(
            id=compute_hash("http://daringfireball.net/index.xml"),
            feed_url="http://daringfireball.net/index.xml",
            name="Daring Fireball - correct",
            subscribed=True,
            full_text=True)

        self.assertNotEqual(instance, None)

        instance.put()


class TestAdminPageLoad(TestbedTest):
    def setUp(self):
        self.common()

    def test_page_load(self):
        response = self.testapp.get('/_admin')

        self.assertEqual(response.status, '200 OK')

    def test_feed_list(self):
        sub = Subscription(
            id=compute_hash("http://daringfireball.net/index.xml"),
            feed_url="http://daringfireball.net/index.xml",
            name="Daring Fireball",
            subscribed=True,
            full_text=True)

        self.assertNotEqual(sub, None)
        sub.put()

        subs = Subscription.query().fetch(100)
        self.assertEqual(len(subs), 1)

        response = self.testapp.get('/feeds')

        for sub in subs:
            self.assertTrue(sub.name in str(response))
            self.assertTrue(str(sub.key.id()) in str(response))

    def test_add_feed(self):
        subs = Subscription.query().fetch(100)
        self.assertEqual(len(subs), 0)

        # The /feeds handler basically takes this and runs the same Subscription
        #   instantiation code as used above, but imports Subscription from models
        # This errors out with the same "Expected Key('Subscription', 123), got 
        #   Key('Subscription', 123)" error
        response = self.testapp.post('/feeds', {
            'add-new': '',
            'name': 'mysub',
            'url': 'http://example.com/feed.xml',
            'subscribed': False
            })

        subs = Subscription.query().fetch(100)
        self.assertEqual(len(subs), 1)

        for sub in subs:
            self.assertTrue(sub.name in str(response))
            self.assertTrue(str(sub.key.id()) in str(response))

if __name__ == '__main__':
    unittest.main()

trace.log

###
# If I comment the Subscription definition and import it instead from the models module, 
#   this is the result
#

(urlfetch)argent:urlfetch sivy$ nosetests -v test.test_admin
test_db_put (test.test_admin.TestDbPutCase) ... ok

----------------------------------------------------------------------
Ran 1 test in 0.015s

OK
(urlfetch)argent:urlfetch sivy$ nosetests -v test.test_admin --with-gae
WARNING:root:The rdbms API is not available because the MySQLdb library could not be loaded.
test_db_put (test.test_admin.TestDbPutCase) ... ERROR

======================================================================
ERROR: test_db_put (test.test_admin.TestDbPutCase)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/Users/sivy/Projects/urlfetch/test/test_admin.py", line 74, in test_db_put
    instance.put()
  File "/Applications/GoogleAppEngineLauncher.app/Contents/Resources/GoogleAppEngine-default.bundle/Contents/Resources/google_appengine/google/appengine/ext/ndb/model.py", line 3003, in _put
    return self._put_async(**ctx_options).get_result()
  File "/Applications/GoogleAppEngineLauncher.app/Contents/Resources/GoogleAppEngine-default.bundle/Contents/Resources/google_appengine/google/appengine/ext/ndb/tasklets.py", line 322, in get_result
    self.check_success()
  File "/Applications/GoogleAppEngineLauncher.app/Contents/Resources/GoogleAppEngine-default.bundle/Contents/Resources/google_appengine/google/appengine/ext/ndb/tasklets.py", line 317, in check_success
    self.wait()
  File "/Applications/GoogleAppEngineLauncher.app/Contents/Resources/GoogleAppEngine-default.bundle/Contents/Resources/google_appengine/google/appengine/ext/ndb/tasklets.py", line 301, in wait
    if not ev.run1():
  File "/Applications/GoogleAppEngineLauncher.app/Contents/Resources/GoogleAppEngine-default.bundle/Contents/Resources/google_appengine/google/appengine/ext/ndb/eventloop.py", line 219, in run1
    delay = self.run0()
  File "/Applications/GoogleAppEngineLauncher.app/Contents/Resources/GoogleAppEngine-default.bundle/Contents/Resources/google_appengine/google/appengine/ext/ndb/eventloop.py", line 181, in run0
    callback(*args, **kwds)
  File "/Applications/GoogleAppEngineLauncher.app/Contents/Resources/GoogleAppEngine-default.bundle/Contents/Resources/google_appengine/google/appengine/ext/ndb/context.py", line 170, in _finished_callback
    fut.check_success()
  File "/Applications/GoogleAppEngineLauncher.app/Contents/Resources/GoogleAppEngine-default.bundle/Contents/Resources/google_appengine/google/appengine/ext/ndb/tasklets.py", line 362, in _help_tasklet_along
    value = gen.send(val)
  File "/Applications/GoogleAppEngineLauncher.app/Contents/Resources/GoogleAppEngine-default.bundle/Contents/Resources/google_appengine/google/appengine/ext/ndb/context.py", line 275, in _put_tasklet
    'Expected %r, got %r' % (key, ent._key))
BadKeyError: Entity key differs from the one returned by the datastore. Expected Key('Subscription', '7153b45584f3b1e58a7b978f92f28213d3c01ce9'), got Key('Subscription', '7153b45584f3b1e58a7b978f92f28213d3c01ce9')
-------------------- >> begin captured stdout << ---------------------
[{
    "model": "subscription",
    "feed_url": "http://daringfireball.net/index.xml",
    "name": "Daring Fireball - correct",
    "subscribed": true,
    "full_text": true
}]

--------------------- >> end captured stdout << ----------------------
-------------------- >> begin captured logging << --------------------
root: WARNING: Could not read datastore data from /var/folders/nr/_00nv5dj3591hcv5q37dc6wr0000gn/T/nosegae.datastore
root: DEBUG: Enabling jinja2: ['_debugsupport', '_speedups']
root: DEBUG: Enabling markupsafe: ['_speedups']
root: DEBUG: Enabling lxml: ['etree', 'objectify']
root: DEBUG: Enabling setuptools: []
root: INFO: zipimporter('/Users/sivy/.virtualenvs/urlfetch/lib/python2.7/site-packages/setuptools-0.6c11-py2.7.egg', '')
root: DEBUG: Not using threading.local
root: DEBUG: Third party package lxml was enabled in app.yaml but not found on import. You may have to download and install it.
root: DEBUG: Third party package markupsafe was enabled in app.yaml but not found on import. You may have to download and install it.
root: DEBUG: Third party package jinja2 was enabled in app.yaml but not found on import. You may have to download and install it.
root: WARNING: FIXTURE LOAD_DATA
test.fixture: INFO: None
test.fixture: INFO: Subscription<categories=StringProperty('categories', repeated=True), confirmed_time=DateTimeProperty('confirmed_time'), etag=StringProperty('etag'), feed_url=TextProperty('feed_url'), full_text=BooleanProperty('full_text', default=False), is_pubsub=BooleanProperty('is_pubsub', default=False), last_updated=DateTimeProperty('last_updated'), name=StringProperty('name'), password=StringProperty('password'), subscribed=BooleanProperty('subscribed', default=True), type=StringProperty('type'), username=StringProperty('username')>
root: DEBUG: Subscription(key=Key('Subscription', 1), categories=[], feed_url=u'http://daringfireball.net/index.xml', full_text=True, is_pubsub=False, name=u'Daring Fireball - correct', subscribed=True)
root: DEBUG: all_pending: add <Future 10b6d3590 created by _put_async(model.py:3019) for tasklet put(context.py:659); result Key('Subscription', 1)>
root: DEBUG: nowevent: _help_tasklet_along
root: DEBUG: Sending None to initial generator put(context.py:659)
root: DEBUG: all_pending: add <Future 10b6d3890 created by add(context.py:137) for AutoBatcher(_put_tasklet).add(Subscription(key=Key('Subscription', None), feed_url='http://daringfireball.net/index.xml', full_text=True, name='Daring Fireball - correct', subscribed=True), None); result Key('Subscription', 1)>
root: DEBUG: AutoBatcher(_put_tasklet): creating new queue for None
root: DEBUG: initial generator put(context.py:659) yielded <Future 10b6d3890 created by add(context.py:137) for AutoBatcher(_put_tasklet).add(Subscription(key=Key('Subscription', None), feed_url='http://daringfireball.net/index.xml', full_text=True, name='Daring Fireball - correct', subscribed=True), None); result Key('Subscription', 1)>
root: DEBUG: <Future 10b6d3590 created by _put_async(model.py:3019) for tasklet put(context.py:659); result Key('Subscription', 1)> is now blocked waiting for <Future 10b6d3890 created by add(context.py:137) for AutoBatcher(_put_tasklet).add(Subscription(key=Key('Subscription', None), feed_url='http://daringfireball.net/index.xml', full_text=True, name='Daring Fireball - correct', subscribed=True), None); result Key('Subscription', 1)>
root: DEBUG: idler: _on_idle
root: DEBUG: AutoBatcher(_put_tasklet): 1 items
root: DEBUG: all_pending: add <Future 10b6d3b50 created by run_queue(context.py:126) for tasklet _put_tasklet(context.py:259); result None>
root: DEBUG: nowevent: _help_tasklet_along
root: DEBUG: Sending None to initial generator _put_tasklet(context.py:259)
root: DEBUG: initial generator _put_tasklet(context.py:259) yielded <google.appengine.api.apiproxy_stub_map.UserRPC object at 0x10b6d3f10>
root: DEBUG: idler: _on_idle
root: DEBUG: idler _on_idle removed
root: DEBUG: rpc: datastore_v3.Put
root: DEBUG: Sending [Key('Subscription', 1)] to suspended generator _put_tasklet(context.py:269)
root: DEBUG: all_pending: success: remove <Future 10b6d3890 created by add(context.py:137) for AutoBatcher(_put_tasklet).add(Subscription(key=Key('Subscription', None), feed_url='http://daringfireball.net/index.xml', full_text=True, name='Daring Fireball - correct', subscribed=True), None); result Key('Subscription', 1)>
root: DEBUG: suspended generator _put_tasklet(context.py:269) returned None
root: DEBUG: all_pending: success: remove <Future 10b6d3b50 created by run_queue(context.py:126) for tasklet _put_tasklet(context.py:259); result None>
root: DEBUG: nowevent: _on_future_completion
root: DEBUG: <Future 10b6d3590 created by _put_async(model.py:3019) for tasklet put(context.py:659); result Key('Subscription', 1)> is no longer blocked waiting for <Future 10b6d3890 created by add(context.py:137) for AutoBatcher(_put_tasklet).add(Subscription(key=Key('Subscription', None), feed_url='http://daringfireball.net/index.xml', full_text=True, name='Daring Fireball - correct', subscribed=True), None); result Key('Subscription', 1)>
root: DEBUG: Sending Key('Subscription', 1) to suspended generator put(context.py:686)
root: DEBUG: all_pending: add <Future 10b6d8590 created by add(context.py:137) for AutoBatcher(_memcache_del_tasklet).add(NDB9:agp1bnBhcnRpYWwychILEgxTdWJzY3JpcHRpb24YAQw, (0, '')); result 1>
root: DEBUG: AutoBatcher(_memcache_del_tasklet): creating new queue for (0, '')
root: DEBUG: suspended generator put(context.py:686) yielded <Future 10b6d8590 created by add(context.py:137) for AutoBatcher(_memcache_del_tasklet).add(NDB9:agp1bnBhcnRpYWwychILEgxTdWJzY3JpcHRpb24YAQw, (0, '')); result 1>
root: DEBUG: <Future 10b6d3590 created by _put_async(model.py:3019) for tasklet put(context.py:659); result Key('Subscription', 1)> is now blocked waiting for <Future 10b6d8590 created by add(context.py:137) for AutoBatcher(_memcache_del_tasklet).add(NDB9:agp1bnBhcnRpYWwychILEgxTdWJzY3JpcHRpb24YAQw, (0, '')); result 1>
root: DEBUG: nowevent: _finished_callback
root: DEBUG: idler: _on_idle
root: DEBUG: AutoBatcher(_memcache_del_tasklet): 1 items
root: DEBUG: all_pending: add <Future 10b6d8c10 created by run_queue(context.py:126) for tasklet _memcache_del_tasklet(context.py:986); result None>
root: DEBUG: nowevent: _help_tasklet_along
root: DEBUG: Sending None to initial generator _memcache_del_tasklet(context.py:986)
root: DEBUG: initial generator _memcache_del_tasklet(context.py:986) yielded <google.appengine.api.apiproxy_stub_map.UserRPC object at 0x10b6dc090>
root: DEBUG: idler: _on_idle
root: DEBUG: idler _on_idle removed
root: DEBUG: rpc: memcache.Delete
root: DEBUG: Sending [1] to suspended generator _memcache_del_tasklet(context.py:995)
root: DEBUG: all_pending: success: remove <Future 10b6d8590 created by add(context.py:137) for AutoBatcher(_memcache_del_tasklet).add(NDB9:agp1bnBhcnRpYWwychILEgxTdWJzY3JpcHRpb24YAQw, (0, '')); result 1>
root: DEBUG: suspended generator _memcache_del_tasklet(context.py:995) returned None
root: DEBUG: all_pending: success: remove <Future 10b6d8c10 created by run_queue(context.py:126) for tasklet _memcache_del_tasklet(context.py:986); result None>
root: DEBUG: nowevent: _on_future_completion
root: DEBUG: <Future 10b6d3590 created by _put_async(model.py:3019) for tasklet put(context.py:659); result Key('Subscription', 1)> is no longer blocked waiting for <Future 10b6d8590 created by add(context.py:137) for AutoBatcher(_memcache_del_tasklet).add(NDB9:agp1bnBhcnRpYWwychILEgxTdWJzY3JpcHRpb24YAQw, (0, '')); result 1>
root: DEBUG: Sending 1 to suspended generator put(context.py:694)
root: DEBUG: suspended generator put(context.py:694) returned Key('Subscription', 1)
root: DEBUG: all_pending: success: remove <Future 10b6d3590 created by _put_async(model.py:3019) for tasklet put(context.py:659); result Key('Subscription', 1)>
root: DEBUG: all_pending: add <Future 10b6dc550 created by _put_async(model.py:3019) for tasklet put(context.py:659) suspended generator put(context.py:686); pending>
root: DEBUG: nowevent: _finished_callback
root: DEBUG: nowevent: _help_tasklet_along
root: DEBUG: Sending None to initial generator put(context.py:659)
root: DEBUG: all_pending: add <Future 10b6dc890 created by add(context.py:137) for AutoBatcher(_memcache_set_tasklet).add(('NDB9:agp1bnBhcnRpYWwycjoLEgxTdWJzY3JpcHRpb24iKDcxNTNiNDU1ODRmM2IxZTU4YTdiOTc4ZjkyZjI4MjEzZDNjMDFjZTkM', 0), ('set', 32, '')); result True>
root: DEBUG: AutoBatcher(_memcache_set_tasklet): creating new queue for ('set', 32, '')
root: DEBUG: initial generator put(context.py:659) yielded <Future 10b6dc890 created by add(context.py:137) for AutoBatcher(_memcache_set_tasklet).add(('NDB9:agp1bnBhcnRpYWwycjoLEgxTdWJzY3JpcHRpb24iKDcxNTNiNDU1ODRmM2IxZTU4YTdiOTc4ZjkyZjI4MjEzZDNjMDFjZTkM', 0), ('set', 32, '')); result True>
root: DEBUG: <Future 10b6dc550 created by _put_async(model.py:3019) for tasklet put(context.py:659) suspended generator put(context.py:686); pending> is now blocked waiting for <Future 10b6dc890 created by add(context.py:137) for AutoBatcher(_memcache_set_tasklet).add(('NDB9:agp1bnBhcnRpYWwycjoLEgxTdWJzY3JpcHRpb24iKDcxNTNiNDU1ODRmM2IxZTU4YTdiOTc4ZjkyZjI4MjEzZDNjMDFjZTkM', 0), ('set', 32, '')); result True>
root: DEBUG: idler: _on_idle
root: DEBUG: AutoBatcher(_memcache_set_tasklet): 1 items
root: DEBUG: all_pending: add <Future 10b6dcc50 created by run_queue(context.py:126) for tasklet _memcache_set_tasklet(context.py:968); result None>
root: DEBUG: nowevent: _help_tasklet_along
root: DEBUG: Sending None to initial generator _memcache_set_tasklet(context.py:968)
root: DEBUG: initial generator _memcache_set_tasklet(context.py:968) yielded <google.appengine.api.apiproxy_stub_map.UserRPC object at 0x10b6dd0d0>
root: DEBUG: idler: _on_idle
root: DEBUG: idler _on_idle removed
root: DEBUG: rpc: memcache.Set
root: DEBUG: Sending {'NDB9:agp1bnBhcnRpYWwycjoLEgxTdWJzY3JpcHRpb24iKDcxNTNiNDU1ODRmM2IxZTU4YTdiOTc4ZjkyZjI4MjEzZDNjMDFjZTkM': 1} to suspended generator _memcache_set_tasklet(context.py:978)
root: DEBUG: all_pending: success: remove <Future 10b6dc890 created by add(context.py:137) for AutoBatcher(_memcache_set_tasklet).add(('NDB9:agp1bnBhcnRpYWwycjoLEgxTdWJzY3JpcHRpb24iKDcxNTNiNDU1ODRmM2IxZTU4YTdiOTc4ZjkyZjI4MjEzZDNjMDFjZTkM', 0), ('set', 32, '')); result True>
root: DEBUG: suspended generator _memcache_set_tasklet(context.py:978) returned None
root: DEBUG: all_pending: success: remove <Future 10b6dcc50 created by run_queue(context.py:126) for tasklet _memcache_set_tasklet(context.py:968); result None>
root: DEBUG: nowevent: _on_future_completion
root: DEBUG: <Future 10b6dc550 created by _put_async(model.py:3019) for tasklet put(context.py:659) suspended generator put(context.py:686); pending> is no longer blocked waiting for <Future 10b6dc890 created by add(context.py:137) for AutoBatcher(_memcache_set_tasklet).add(('NDB9:agp1bnBhcnRpYWwycjoLEgxTdWJzY3JpcHRpb24iKDcxNTNiNDU1ODRmM2IxZTU4YTdiOTc4ZjkyZjI4MjEzZDNjMDFjZTkM', 0), ('set', 32, '')); result True>
root: DEBUG: Sending True to suspended generator put(context.py:679)
root: DEBUG: all_pending: add <Future 10b6dd510 created by add(context.py:137) for AutoBatcher(_put_tasklet).add(Subscription(key=Key('Subscription', '7153b45584f3b1e58a7b978f92f28213d3c01ce9'), feed_url='http://daringfireball.net/index.xml', full_text=True, name='Daring Fireball - correct', subscribed=True), None); pending>
root: DEBUG: AutoBatcher(_put_tasklet): creating new queue for None
root: DEBUG: suspended generator put(context.py:679) yielded <Future 10b6dd510 created by add(context.py:137) for AutoBatcher(_put_tasklet).add(Subscription(key=Key('Subscription', '7153b45584f3b1e58a7b978f92f28213d3c01ce9'), feed_url='http://daringfireball.net/index.xml', full_text=True, name='Daring Fireball - correct', subscribed=True), None); pending>
root: DEBUG: <Future 10b6dc550 created by _put_async(model.py:3019) for tasklet put(context.py:659) suspended generator put(context.py:686); pending> is now blocked waiting for <Future 10b6dd510 created by add(context.py:137) for AutoBatcher(_put_tasklet).add(Subscription(key=Key('Subscription', '7153b45584f3b1e58a7b978f92f28213d3c01ce9'), feed_url='http://daringfireball.net/index.xml', full_text=True, name='Daring Fireball - correct', subscribed=True), None); pending>
root: DEBUG: nowevent: _finished_callback
root: DEBUG: idler: _on_idle
root: DEBUG: AutoBatcher(_put_tasklet): 1 items
root: DEBUG: all_pending: add <Future 10b6dd890 created by run_queue(context.py:126) for tasklet _put_tasklet(context.py:259); exception BadKeyError: Entity key differs from the one returned by the datastore. Expected Key('Subscription', '7153b45584f3b1e58a7b978f92f28213d3c01ce9'), got Key('Subscription', '7153b45584f3b1e58a7b978f92f28213d3c01ce9')>
root: DEBUG: nowevent: _help_tasklet_along
root: DEBUG: Sending None to initial generator _put_tasklet(context.py:259)
root: DEBUG: initial generator _put_tasklet(context.py:259) yielded <google.appengine.api.apiproxy_stub_map.UserRPC object at 0x10b6ddd50>
root: DEBUG: idler: _on_idle
root: DEBUG: idler _on_idle removed
root: DEBUG: rpc: datastore_v3.Put
root: DEBUG: Sending [Key('Subscription', '7153b45584f3b1e58a7b978f92f28213d3c01ce9')] to suspended generator _put_tasklet(context.py:269)
root: WARNING: suspended generator _put_tasklet(context.py:269) raised BadKeyError(Entity key differs from the one returned by the datastore. Expected Key('Subscription', '7153b45584f3b1e58a7b978f92f28213d3c01ce9'), got Key('Subscription', '7153b45584f3b1e58a7b978f92f28213d3c01ce9'))
Traceback (most recent call last):
  File "/Applications/GoogleAppEngineLauncher.app/Contents/Resources/GoogleAppEngine-default.bundle/Contents/Resources/google_appengine/google/appengine/ext/ndb/tasklets.py", line 362, in _help_tasklet_along
    value = gen.send(val)
  File "/Applications/GoogleAppEngineLauncher.app/Contents/Resources/GoogleAppEngine-default.bundle/Contents/Resources/google_appengine/google/appengine/ext/ndb/context.py", line 275, in _put_tasklet
    'Expected %r, got %r' % (key, ent._key))
BadKeyError: Entity key differs from the one returned by the datastore. Expected Key('Subscription', '7153b45584f3b1e58a7b978f92f28213d3c01ce9'), got Key('Subscription', '7153b45584f3b1e58a7b978f92f28213d3c01ce9')
root: DEBUG: all_pending: fail: remove <Future 10b6dd890 created by run_queue(context.py:126) for tasklet _put_tasklet(context.py:259); exception BadKeyError: Entity key differs from the one returned by the datastore. Expected Key('Subscription', '7153b45584f3b1e58a7b978f92f28213d3c01ce9'), got Key('Subscription', '7153b45584f3b1e58a7b978f92f28213d3c01ce9')>
root: DEBUG: nowevent: _finished_callback
--------------------- >> end captured logging << ---------------------

----------------------------------------------------------------------
Ran 1 test in 0.076s

FAILED (errors=1)
(urlfetch)argent:urlfetch sivy$ 

Hi, I am facing exactly the same problem. Did you find any solution?.

Thanks.