Issue #69 new

KeyError on some transactions?

eric carmichael
created an issue

KeyError: 'trans_savepoint_default_s140250199967488_x1'

First of all, thanks for johnny-cache, I'm really excited to see how it helps my site :)

I haven't had any problems with it until now, I get a KeyError at this point:

  File "/home/mysite/mysite/local/lib/python2.7/site-packages/johnny/transaction.py", line 235, in _commit_all_savepoints
    self._commit_savepoint(sids[0], using)

  File "/home/mysite/mysite/local/lib/python2.7/site-packages/johnny/transaction.py", line 224, in _commit_savepoint
    for k, v in self.local[i].iteritems():

  File "/home/mysite/mysite/local/lib/python2.7/site-packages/johnny/localstore.py", line 22, in __getitem__
    return self.__dict__[key]

KeyError: 'trans_savepoint_default_s140250199967488_x1'

This is happening when I open a pop-up window to add a category to my Zinnia blog app. Also, this happened when I post the very first post in a forum on pybb. Do I need to add something to the hilariously named man-in-the-black-list?!

Thanks again for this great app! :)

Comments (10)

  1. ustun

    I have the same issue too, it seems like the localstore is being cleaned up somehow. Are you running any customized save() methods, and/or celery?

  2. eric carmichael reporter

    Nope - no custom save() or celery. However, maybe the apps I'm using are...

    Sometime soon I'll take a peek at customizing the cache so it ignores things like adding forum posts/blog entries.

    Thanks for the reply!

  3. ustun

    Eric, can you reproduce the issue always? What happens when you replace the last line of _create_savepoint() function in transaction.py with this?

    Instead of:

    sids.append(key)
    

    try this

    if len(sids) > 0 and sids[-1] != key:
        sids.append(key)
    

    My understanding is that in some cases, the same savepoint id is returned, so, "sids" stack contains the same value twice. While popping, only one of this popped later on, causing the dict lookup to fail.

    Here are some logs I have collected by putting logging into various set/get methods there:

    WARNING 2012-11-05 15:53:40,957 localstore 97753 140735106027904 initializing localstore

    WARNING 2012-11-05 15:53:42,153 localstore 97753 140735106027904 set item localstore trans_sids {}

    WARNING 2012-11-05 15:53:47,993 transaction 97753 140735106027904 in savepoint

    WARNING 2012-11-05 15:53:47,994 localstore 97753 140735106027904 set item localstore trans_savepoint_default_s140735106027904_x1 {}

    WARNING 2012-11-05 15:53:52,235 localstore 97753 140735106027904 clearing the localstore

    WARNING 2012-11-05 15:53:52,236 localstore 97753 140735106027904 get item localstore trans_sids

    WARNING 2012-11-05 15:53:52,236 transaction 97753 140735106027904 sids ['trans_savepoint_default_s140735106027904_x1']

    WARNING 2012-11-05 15:53:52,270 transaction 97753 140735106027904 in savepoint

    WARNING 2012-11-05 15:53:54,557 localstore 97753 140735106027904 clearing the localstore

    WARNING 2012-11-05 15:53:54,558 localstore 97753 140735106027904 get item localstore trans_sids

    WARNING 2012-11-05 15:53:54,558 transaction 97753 140735106027904 sids ['trans_savepoint_default_s140735106027904_x1', 'trans_savepoint_default_s140735106027904_x1']

    WARNING 2012-11-05 15:53:54,563 transaction 97753 140735106027904 in savepoint commmit

    WARNING 2012-11-05 15:53:54,563 localstore 97753 140735106027904 get item localstore trans_sids

    WARNING 2012-11-05 15:53:54,563 localstore 97753 140735106027904 set item localstore trans_dirty_store_default {}

    WARNING 2012-11-05 15:54:07,984 localstore 97753 140735106027904 clearing the localstore

    WARNING 2012-11-05 15:54:07,984 localstore 97753 140735106027904 get item localstore trans_savepoint_default_s140735106027904_x1

    WARNING 2012-11-05 15:54:09,705 transaction 97753 140735106027904 in savepoint commmit

    WARNING 2012-11-05 15:54:09,706 localstore 97753 140735106027904 get item localstore trans_sids

    WARNING 2012-11-05 15:54:09,706 localstore 97753 140735106027904 set item localstore trans_dirty_store_default {}

    WARNING 2012-11-05 15:54:11,474 localstore 97753 140735106027904 clearing the localstore

    WARNING 2012-11-05 15:54:11,475 localstore 97753 140735106027904 get item localstore trans_savepoint_default_s140735106027904_x1

    WARNING 2012-11-05 15:54:11,475 localstore 97753 140735106027904 error retrieving key trans_savepoint_default_s140735106027904_x1

    Observe the following line above:

    WARNING 2012-11-05 15:53:54,558 transaction 97753 140735106027904
    

    sids ['trans_savepoint_default_s140735106027904_x1',
    'trans_savepoint_default_s140735106027904_x1']`

    I am still not sure that the fix I suggested above fixes the issue, or silently ignores it though.

    One more question: Are you using get_or_create's in that buggy region? I am using it, and it seems that it is the one creating those savepoints. See https://github.com/django/django/blob/master/django/db/models/query.py#L447

  4. ustun

    Looking further, it seems the savepoint method at https://github.com/django/django/blob/master/django/db/backends/init.py#L242 is returning the same value for the thread each time.

    It seems that savepoint_state is being incremented by 1, so for example, I would expect the above sids array to be 'trans_savepoint_default_s140735106027904_x1', 'trans_savepoint_default_s140735106027904_x2']`

    So, _x2 instead of _x1. Since it is not so, I am assuming that object is not reused, but a new DatabaseWrapper is used, whose savepoint_state is 0.

    EDIT: It seems not a new object is used, but clean_savepoints is used to reset the value.

  5. ustun

    It seems that the issue can be worked around by not using get_or_create for me in this case, as this prevents savepoints being created by it; however I would be happy to see if anyone else can reproduce the problem or make some suggestions.

  6. eric carmichael reporter

    Hrm.

    Yeah, sometimes you can't get around NOT using get_or_create, because so many of the apps we depend on use it.

    The first fix you posted, checking length before appending the key, seems to have fixed my problem for now!

    Thank you very much ustun.

  7. Emil Stenström

    We're also seeing this error or a fairly big site.

    Using MySQL and Django 1.4.

    This line is causing this problem for us: self.class.objects.filter(id=self.id).update(**kwargs)

    We're using this to bypass triggering Django signals when updating a post.

  8. Log in to comment