django deleted row exists?

Question

I am facing a very peculiar problem that even when I delete some rows, I can just get them back again in same transaction. I am running this under apache and mod_wsgi, database is mysql.

Edit: I have created a sample app to test it out, so that I can be sure that none of my code is culprit.

I created a testapp with following code

models.py

import uuid
from django.db import models

class TestTable(models.Model):
    id = models.CharField(max_length=36, primary_key=True)
    name = models.CharField(max_length=50)

    @classmethod
    def get_row(cls, name):
        return TestTable(id=str(uuid.uuid4()), name=name)

    def __unicode__(self):
        return u"%s[%s]"%(self.name, self.id)

views.py

import traceback
import time
from django.db import transaction
from django.http import HttpResponse

from testapp.models import TestTable

@transaction.commit_manually
def test_view(request):
    time.sleep(1)
    out = []
    try:
        # delete 3 rows
        for row in TestTable.objects.all()[:3]:
            ID=row.id
            out.append("deleting %s"%row)
            row.delete()
            # check fi really deleted
            try:
                TestTable.objects.get(id=ID)
                out.append("row not deleted?")
            except TestTable.DoesNotExist,e:
                out.append("row deleted.")

        # create 5 rows
        for i in range(5):
            row = TestTable.get_row("row %s"%i)
            row.save()

    except Exception,e:
        out.append("Error:%s"%traceback.format_exc())
        transaction.rollback()
    else:
        transaction.commit()

    return HttpResponse('\n'.join(out), 'text/text')

urls.py

from django.conf.urls.defaults import *

urlpatterns = patterns('testapp.views', (r'^test_bug$', 'test_view')

TestScript

import urllib2
from multiprocessing import Process

def get_data():
    r = urllib2.urlopen("http://localhost:81/timeapp/test/test_bug")
    print "---------"
    print r.read()

if __name__ == "__main__":
    for i in range(2):
        p = Process(target=get_data)
        p.start()

Output:

$ python test.py 
---------
deleting row 1[3ad3a82e-830f-4540-8148-88479175ed5e]
row deleted.
deleting row 0[544462d1-8588-4a8c-a809-16a060054479]
row deleted.
deleting row 3[55d422f3-6c39-4c26-943a-1b4db498bf25]
row deleted.
---------
deleting row 1[3ad3a82e-830f-4540-8148-88479175ed5e]
row not deleted?
deleting row 0[544462d1-8588-4a8c-a809-16a060054479]
row not deleted?
deleting row 3[55d422f3-6c39-4c26-943a-1b4db498bf25]
row not deleted?

So my question is how come deleted row is again retrievable by TestTable.objects.get, also even if I sleep more in second call so that first call can commit code I still get deleted rows in second call.

Answer 1

I doubt your problem is what you think it is. Note that the second time you don't get the exception printed.

The trouble is, you are catching all exceptions, instead of just the one you handle, 'TimeCardDetail.DoesNotExist'. This masks the real problem when something unexpected happens. Replace the catch-all 'except Exception' with that specific exception, and see what happens.

Answer 2

You may be dealing with a lookup of cached objects. Additionally, if you are dealing with cached objects they are probably only showing up with your apache setup because the requests are handled in parallel by two different processes. Try reducing the number of apache worker processes to 1 and see if the behavior is the same as when you run it in the dev server(./manage.py runserver).

You can also try adding some timestamps and a dump of the sql being used. Set DEBUG=True in settings.py and then you can look at your raw sql queries.

# views.py
from django.db import connection

def test_view(request):
    connection.queries = []
    start_time = time.time()
    out = []
    out.append("%09.6f" % (time.time() % 100))  # something like 13.45678
    time.sleep(1)
    [...]
        # delete 3 rows
            [...]
            out.append("deleting %s"%row)
            out.append("%09.6f" % (time.time() % 100))
            [...]
            out.append("%d queries after the last delete" %d len(connection.queries))
        # create 5 rows
    [...]
    out.append("%09.6f total time spent" % (time.time() - start_time))
    out.append("%d queries TOTAL" %d len(connection.queries))
    # dump the actual queries if you are still digging.
    for q in connection.queries:
        out.append("%s\n----" % q)

Answer 3

Your problem fascinated me, so I spent quite a bit of time investigating it, and the only conclusion I can come up with is that it's a bona fide bug in either python-MySQL or MySQL itself. Here's what I tried:

I should note that I changed the code slightly so that instead of:

try:
    TestTable.objects.get(id=ID)
    out.append("row not deleted?")
except TestTable.DoesNotExist,e:
    out.append("row deleted.")

I had:

c = TestTable.objects.filter(id=ID).count()
if c:
    out.append("row not deleted?")
else:
    out.append("row deleted.")

This made it slightly easier to debug, and did not affect the manifestation of the problem.

Firstly, Django's caching is not to blame here. The queries to get the counts were issued, as can be seen in the MySQL logs (the 1 and 2 represent the two separate concurrent connections that get made):

1 Query SET NAMES utf8
2 Query SET NAMES utf8
2 Query set autocommit=0
1 Query set autocommit=0
1 Query SELECT `testapp_testtable`.`id`, `testapp_testtable`.`name` FROM `testapp_testtable` LIMIT 3
2 Query SELECT `testapp_testtable`.`id`, `testapp_testtable`.`name` FROM `testapp_testtable` LIMIT 3
2 Query DELETE FROM `testapp_testtable` WHERE `id` IN ('32f027ff-c798-410b-8621-c2d47e2cfa7c')
1 Query DELETE FROM `testapp_testtable` WHERE `id` IN ('32f027ff-c798-410b-8621-c2d47e2cfa7c')
2 Query SELECT COUNT(*) FROM `testapp_testtable` WHERE `testapp_testtable`.`id` = '32f027ff-c798-410b-8621-c2d47e2cfa7c'
2 Query DELETE FROM `testapp_testtable` WHERE `id` IN ('3f693297-9993-4162-98c4-a9ca68232c75')
2 Query SELECT COUNT(*) FROM `testapp_testtable` WHERE `testapp_testtable`.`id` = '3f693297-9993-4162-98c4-a9ca68232c75'
2 Query DELETE FROM `testapp_testtable` WHERE `id` IN ('96f9a1f7-c818-4528-858f-4e85a93de5c3')
2 Query SELECT COUNT(*) FROM `testapp_testtable` WHERE `testapp_testtable`.`id` = '96f9a1f7-c818-4528-858f-4e85a93de5c3'
2 Query SELECT (1) AS `a` FROM `testapp_testtable` WHERE `testapp_testtable`.`id` = '035c90ba-82a6-4bdc-afe1-318382563017'  LIMIT 1
2 Query INSERT INTO `testapp_testtable` (`id`, `name`) VALUES ('035c90ba-82a6-4bdc-afe1-318382563017', 'row 0')
2 Query SELECT (1) AS `a` FROM `testapp_testtable` WHERE `testapp_testtable`.`id` = '15393978-4200-4b98-98e6-73636c39dd1c'  LIMIT 1
2 Query INSERT INTO `testapp_testtable` (`id`, `name`) VALUES ('15393978-4200-4b98-98e6-73636c39dd1c', 'row 1')
2 Query SELECT (1) AS `a` FROM `testapp_testtable` WHERE `testapp_testtable`.`id` = '22459ba2-18d5-4175-ac6b-2377ba63ecc7'  LIMIT 1
2 Query INSERT INTO `testapp_testtable` (`id`, `name`) VALUES ('22459ba2-18d5-4175-ac6b-2377ba63ecc7', 'row 2')
2 Query commit
2 Quit  
1 Query SELECT COUNT(*) FROM `testapp_testtable` WHERE `testapp_testtable`.`id` = '32f027ff-c798-410b-8621-c2d47e2cfa7c'
1 Query DELETE FROM `testapp_testtable` WHERE `id` IN ('3f693297-9993-4162-98c4-a9ca68232c75')
1 Query SELECT COUNT(*) FROM `testapp_testtable` WHERE `testapp_testtable`.`id` = '3f693297-9993-4162-98c4-a9ca68232c75'
1 Query DELETE FROM `testapp_testtable` WHERE `id` IN ('96f9a1f7-c818-4528-858f-4e85a93de5c3')
1 Query SELECT COUNT(*) FROM `testapp_testtable` WHERE `testapp_testtable`.`id` = '96f9a1f7-c818-4528-858f-4e85a93de5c3'
1 Query SELECT (1) AS `a` FROM `testapp_testtable` WHERE `testapp_testtable`.`id` = '6dc6e901-bebe-4f3b-98d1-c8c4a90d06df'  LIMIT 1
1 Query INSERT INTO `testapp_testtable` (`id`, `name`) VALUES ('6dc6e901-bebe-4f3b-98d1-c8c4a90d06df', 'row 0')
1 Query SELECT (1) AS `a` FROM `testapp_testtable` WHERE `testapp_testtable`.`id` = 'c335ccad-31c6-4ddd-bccd-578435cd6e7b'  LIMIT 1
1 Query INSERT INTO `testapp_testtable` (`id`, `name`) VALUES ('c335ccad-31c6-4ddd-bccd-578435cd6e7b', 'row 1')
1 Query SELECT (1) AS `a` FROM `testapp_testtable` WHERE `testapp_testtable`.`id` = '2c507629-a87e-48ec-b80d-2f758cd16c44'  LIMIT 1
1 Query INSERT INTO `testapp_testtable` (`id`, `name`) VALUES ('2c507629-a87e-48ec-b80d-2f758cd16c44', 'row 2')
1 Query commit
1 Quit  

And of course, any subsequent attempts at fetching the count after the session is closed show that the row was in fact deleted. Furthermore, logging the received SQL results in django.db.models.sql.query shows that the SELECT COUNT statements immediately following the DELETE statements in the second half of the above log in fact returned 1, instead of the 0 one would expect. I have no explanation for this.

As far as I can tell, there are only two options available to get the functionality you want. I've verified that both of them work:

• In your Apache conf, set MaxClients and ThreadsPerChild to 1 (not a very practical option).
• Use PostgreSQL (I would recommend this to anyone using MySQL anyway).

Answer 4

It looks to me as if you have a variant of this ticket reported at djangoproject.com.