I sometimes get a KeyError when doing something with References

[Matt Haggard]

I sometimes get this error:

Traceback (most recent call last):
  File "test_failer.py", line 134, in <module>
    runtest(store)
  File "test_failer.py", line 107, in runtest
    c.addQuestionnaire()
  File "/vagrant/smd/smd/customer.py", line 190, in addQuestionnaire
    if self.currentQuestionnaire():
  File "/vagrant/smd/smd/customer.py", line 175, in currentQuestionnaire
    Coalesce(self.validation_type, u''))
  File "/vagrant/storm/storm/store.py", line 1660, in find
    self._store.flush()
  File "/vagrant/storm/storm/store.py", line 497, in flush
    self._flush_one(obj_info)
  File "/vagrant/storm/storm/store.py", line 575, in _flush_one
    obj_info.event.emit("flushed")
  File "/vagrant/storm/storm/references.py", line 843, in _break_on_remote_flushed
    self.unlink(local_info, remote_info)
  File "/vagrant/storm/storm/references.py", line 733, in unlink
    local_store.remove_flush_order(remote_info, local_info)
  File "/vagrant/storm/storm/store.py", line 432, in remove_flush_order
    raise e
KeyError: ({<storm.references.Relation object at 0xcb6b410>: {}, 'primary_vars': (<storm.variables.IntVariable object at 0xcb67398>,), 'store': <storm.store.Store object at 0x2fb8f50>, 'sequence': 4}, {<storm.references.Relation object at 0x2e90dd0>: {'flush_order': set([{<storm.references.Relation object at 0xcb6b410>: {}, 'primary_vars': (<storm.variables.IntVariable object at 0xcb67398>,), 'store': <storm.store.Store object at 0x2fb8f50>, 'sequence': 4}])}, 'primary_vars': (<storm.variables.IntVariable object at 0xcc4e320>,), 'store': <storm.store.Store object at 0x2fb8f50>, 'sequence': 1})

And "sometimes" really means "sometimes." I have a piece of production code (that I'm whittling down) that I can repeatedly run and frequently get that traceback. I suspect it has something to do with weakrefs.

It seems like the problem is that a pair is added to the Store with Store.add_flush_order(...) then Store._order is cleared within Store.flush(). Then Relation.unlink(...) finds a "flush_order" that wasn't cleared at the same time Store._order was cleared, tries to remove it with Store.remove_flush_order(...) and raises that error.

The following change to store.py prevents the error, but I'm not sure if that's the spot to prevent it:

diff --git a/storm/store.py b/storm/store.py
index 0213073..fa37633 100644
--- a/storm/store.py
+++ b/storm/store.py
@@ -484,6 +484,11 @@ class Store(object):
                 self._dirty.pop(obj_info, None)
                 self._flush_one(obj_info)

+ for key, value in self._order.items():
+ for obj in key:
+ for k, v in obj.items():
+ if type(v) == dict and 'flush_order' in v:
+ v.pop('flush_order')
         self._order.clear()

         # That's not stricly necessary, but prevents getting into bigints.

[Matt Haggard (iffy)]

FWIW the (sqlite) tests all pass with this change in place.

[Matt Haggard (iffy)]

This usually fails for me. I run it repeatedly like this:

FAILED="0"; SUCCESS="0"; for i in {1..100}; do python test_failer.py; RESULT=$?; if [ ! "$RESULT" -eq 0 ]; then let FAILED=$FAILED+1; else let SUCCESS=$SUCCESS+1; fi; sleep 1; rm -r tmp*; done; echo "Success: $SUCCESS Failed: $FAILED"

I'm working in a clean virtual environment (using virtualenvwrapper) on an Ubuntu 12.04 LTS Vagrant VM.
Python 2.7.3

mktmpenv
pip install -U pip
pip install storm==0.20
FAILED="0"; SUCCESS="0"; for i in {1..100}; do python test_failer.py; RESULT=$?; if [ ! "$RESULT" -eq 0 ]; then let FAILED=$FAILED+1; else let SUCCESS=$SUCCESS+1; fi; sleep 1; rm -r tmp*; done; echo "Success: $SUCCESS Failed: $FAILED"

Here's a typical traceback:
Traceback (most recent call last):
  File "test_failer.py", line 76, in <module>
    runtest(store, <email address hidden>', 10)
  File "test_failer.py", line 68, in runtest
    c = list(store.find(Customer))
  File "/home/vagrant/.virtualenvs/f94aec89-57e6-4d9c-9a63-8a724332410a/local/lib/python2.7/site-packages/storm/store.py", line 221, in find
    self.flush()
  File "/home/vagrant/.virtualenvs/f94aec89-57e6-4d9c-9a63-8a724332410a/local/lib/python2.7/site-packages/storm/store.py", line 501, in flush
    self._flush_one(obj_info)
  File "/home/vagrant/.virtualenvs/f94aec89-57e6-4d9c-9a63-8a724332410a/local/lib/python2.7/site-packages/storm/store.py", line 566, in _flush_one
    obj_info.event.emit("flushed")
  File "/home/vagrant/.virtualenvs/f94aec89-57e6-4d9c-9a63-8a724332410a/local/lib/python2.7/site-packages/storm/references.py", line 831, in _break_on_remote_flushed
    self.unlink(local_info, remote_info)
  File "/home/vagrant/.virtualenvs/f94aec89-57e6-4d9c-9a63-8a724332410a/local/lib/python2.7/site-packages/storm/references.py", line 727, in unlink
    local_store.remove_flush_order(remote_info, local_info)
  File "/home/vagrant/.virtualenvs/f94aec89-57e6-4d9c-9a63-8a724332410a/local/lib/python2.7/site-packages/storm/store.py", line 436, in remove_flush_order
    self._order[pair] -= 1
KeyError: ({'primary_vars': (<storm.variables.IntVariable object at 0x1092500>,), 'store': <storm.store.Store object at 0x1085ad0>, 'sequence': 2}, {'primary_vars': (<storm.variables.IntVariable object at 0x1092578>,), <storm.references.Relation object at 0x108bed0>: {'flush_order': set([{'primary_vars': (<storm.variables.IntVariable object at 0x1092500>,), 'store': <storm.store.Store object at 0x1085ad0>, 'sequence': 2}])}, 'store': <storm.store.Store object at 0x1085ad0>, 'sequence': 1})

I don't see the same behavior when using `virtualenv` (instead of `mktmpenv`). I'm not sure why that makes a difference.

[Matt Haggard (iffy)]

I can get this new test to fail for sqlite and postgres most of the time. I don't have mysql handy for testing.