Issue: Confusing @db.atomic() behavior - transactions don't wrap entire method?
Author: brandond
State: closed
Created: 2019-10-18 02:55:34

I have some code that does a bunch of batch importing from another system. This takes a while and creates/deletes/modifies a bunch of rows across multiple tables. I'd like to do this all in a single transaction so that I can serve read requests while the batch process is running without getting odd partially-processed data.

I have tried wrapping the batch functions in `@atomic()` decorators, or using `with atomic() as transaction`, but neither seem to do what I want. Even when I use immediate or exclusive locks, it still only wraps individual model operations in transactions.

Here's a sample:
```python
#!/usr/bin/env python
# -*- coding: utf-8 -*-

import logging
from peewee import Model
from playhouse.apsw_ext import APSWDatabase, CharField, ForeignKeyField, AutoField

logging.basicConfig(level='DEBUG')
logger = logging.getLogger(__name__)

db = APSWDatabase('test.db',
                  pragmas=(('foreign_keys', 'on'),
                           ('auto_vacuum', 'NONE'),
                           ('journal_mode', 'WAL'),
                           ('locking_mode', 'NORMAL'),
                           ('synchronous', 'NORMAL')))


class BaseModel(Model):
    class Meta:
        database = db
        without_rowid = True
        only_save_dirty = True


class Forum(BaseModel):
    id = AutoField()
    name = CharField()


class Thread(BaseModel):
    id = AutoField()
    name = CharField()
    description = CharField
    forum = ForeignKeyField(model=Forum, backref='threads', on_update='CASCADE', on_delete='CASCADE')


class Post(BaseModel):
    id = AutoField()
    title = CharField()
    body = CharField()
    thread = ForeignKeyField(model=Thread, backref='posts', on_update='CASCADE', on_delete='CASCADE')


with db.connection_context():
    db.create_tables([Forum, Thread, Post], fail_silently=True)


@db.atomic('EXCLUSIVE')
def populate_forum():
    logger.info('Creating post 1')
    save_post('Foo Forum', 'Foo Thread One', 'Test Post 1', 'Question?')
    logger.info('Creating post 2')
    save_post('Bar Forum', 'Bar Thread One', 'Off-Topic', 'Rant, Rave...')
    logger.info('Creating post 3')
    save_post('Foo Forum', 'Foo Thread One', 'Re: Test Post 1', 'Answer.')
    logger.info('Done creating all posts')


@db.atomic('IMMEDIATE')
def save_post(forum_name, thread_name, title, body):
    forum, _ = Forum.get_or_create(name=forum_name)
    thread, _ = Thread.get_or_create(forum=forum, name=thread_name)
    return Post.create(thread=thread, title=title, body=body)


if __name__ == '__main__':
    logger.info('About to call populate')
    populate_forum()
    logger.info('Populate returned')
```

I'm working off the docs here: http://docs.peewee-orm.com/en/latest/peewee/database.html#set-locking-mode-for-transaction

Given the decorators on both `populate_forum` and `save_post`, I would expect to see transactions and/or savepoints created and committed at the start and end of each call, but that's not happening.

Here's what I get:
```
INFO:__main__:About to call populate
INFO:__main__:Creating post 1
DEBUG:peewee:('SAVEPOINT "s937707aee4f546b8b2dcf9fe367dd066";', None)
DEBUG:peewee:('SELECT "t1"."id", "t1"."name" FROM "forum" AS "t1" WHERE ("t1"."name" = ?) LIMIT ? OFFSET ?', [u'Foo Forum', 1, 0])
DEBUG:peewee:('SAVEPOINT "s57afe046777a4d8e83c971ee96dfdabd";', None)
DEBUG:peewee:('INSERT INTO "forum" ("name") VALUES (?)', [u'Foo Forum'])
DEBUG:peewee:('RELEASE SAVEPOINT "s57afe046777a4d8e83c971ee96dfdabd";', None)
DEBUG:peewee:('SELECT "t1"."id", "t1"."name", "t1"."forum_id" FROM "thread" AS "t1" WHERE (("t1"."name" = ?) AND ("t1"."forum_id" = ?)) LIMIT ? OFFSET ?', [u'Foo Thread One', 1, 1, 0])
DEBUG:peewee:('SAVEPOINT "s87d5f1a49c554610bbeb5b1f9ead6a15";', None)
DEBUG:peewee:('INSERT INTO "thread" ("name", "forum_id") VALUES (?, ?)', [u'Foo Thread One', 1])
DEBUG:peewee:('RELEASE SAVEPOINT "s87d5f1a49c554610bbeb5b1f9ead6a15";', None)
DEBUG:peewee:('INSERT INTO "post" ("title", "body", "thread_id") VALUES (?, ?, ?)', [u'Test Post 1', u'Question?', 1])
DEBUG:peewee:('RELEASE SAVEPOINT "s937707aee4f546b8b2dcf9fe367dd066";', None)
INFO:__main__:Creating post 2
DEBUG:peewee:('SAVEPOINT "see2fab7bb9b2445ca3e0d12027e4eddb";', None)
DEBUG:peewee:('SELECT "t1"."id", "t1"."name" FROM "forum" AS "t1" WHERE ("t1"."name" = ?) LIMIT ? OFFSET ?', [u'Bar Forum', 1, 0])
DEBUG:peewee:('SAVEPOINT "s6ae82b0939c9407290ebf66d5ad819eb";', None)
DEBUG:peewee:('INSERT INTO "forum" ("name") VALUES (?)', [u'Bar Forum'])
DEBUG:peewee:('RELEASE SAVEPOINT "s6ae82b0939c9407290ebf66d5ad819eb";', None)
DEBUG:peewee:('SELECT "t1"."id", "t1"."name", "t1"."forum_id" FROM "thread" AS "t1" WHERE (("t1"."name" = ?) AND ("t1"."forum_id" = ?)) LIMIT ? OFFSET ?', [u'Bar Thread One', 2, 1, 0])
DEBUG:peewee:('SAVEPOINT "s65fcebb7fa394bb0ad75af7eedd381f2";', None)
DEBUG:peewee:('INSERT INTO "thread" ("name", "forum_id") VALUES (?, ?)', [u'Bar Thread One', 2])
DEBUG:peewee:('RELEASE SAVEPOINT "s65fcebb7fa394bb0ad75af7eedd381f2";', None)
DEBUG:peewee:('INSERT INTO "post" ("title", "body", "thread_id") VALUES (?, ?, ?)', [u'Off-Topic', u'Rant, Rave...', 2])
DEBUG:peewee:('RELEASE SAVEPOINT "see2fab7bb9b2445ca3e0d12027e4eddb";', None)
INFO:__main__:Creating post 3
DEBUG:peewee:('SAVEPOINT "s4abe0ada7064428bb3715aa6bdab0776";', None)
DEBUG:peewee:('SELECT "t1"."id", "t1"."name" FROM "forum" AS "t1" WHERE ("t1"."name" = ?) LIMIT ? OFFSET ?', [u'Foo Forum', 1, 0])
DEBUG:peewee:('SELECT "t1"."id", "t1"."name", "t1"."forum_id" FROM "thread" AS "t1" WHERE (("t1"."name" = ?) AND ("t1"."forum_id" = ?)) LIMIT ? OFFSET ?', [u'Foo Thread One', 1, 1, 0])
DEBUG:peewee:('INSERT INTO "post" ("title", "body", "thread_id") VALUES (?, ?, ?)', [u'Re: Test Post 1', u'Answer.', 1])
DEBUG:peewee:('RELEASE SAVEPOINT "s4abe0ada7064428bb3715aa6bdab0776";', None)
INFO:__main__:Done creating all posts
INFO:__main__:Populate returned
```

FWIW, if I switch APSWDatabase out for SqliteDatabase I do see it starting an exclusive transaction when populate_forum is entered, but it does not appear to be committed when the function returns? But it is getting committed somehow.

```
INFO:__main__:About to call populate
DEBUG:peewee:('BEGIN EXCLUSIVE', None)
INFO:__main__:Creating post 1
DEBUG:peewee:('SAVEPOINT "s86e3fbb27555458bb1c03c846eabf2e6";', None)
DEBUG:peewee:('SELECT "t1"."id", "t1"."name" FROM "forum" AS "t1" WHERE ("t1"."name" = ?) LIMIT ? OFFSET ?', [u'Foo Forum', 1, 0])
DEBUG:peewee:('SAVEPOINT "s78555c6a162b49209a8963c41b3d2809";', None)
DEBUG:peewee:('INSERT INTO "forum" ("name") VALUES (?)', [u'Foo Forum'])
DEBUG:peewee:('RELEASE SAVEPOINT "s78555c6a162b49209a8963c41b3d2809";', None)
DEBUG:peewee:('SELECT "t1"."id", "t1"."name", "t1"."forum_id" FROM "thread" AS "t1" WHERE (("t1"."name" = ?) AND ("t1"."forum_id" = ?)) LIMIT ? OFFSET ?', [u'Foo Thread One', 1, 1, 0])
DEBUG:peewee:('SAVEPOINT "sf31da5dd91c9409da6de4481f2f98954";', None)
DEBUG:peewee:('INSERT INTO "thread" ("name", "forum_id") VALUES (?, ?)', [u'Foo Thread One', 1])
DEBUG:peewee:('RELEASE SAVEPOINT "sf31da5dd91c9409da6de4481f2f98954";', None)
DEBUG:peewee:('INSERT INTO "post" ("title", "body", "thread_id") VALUES (?, ?, ?)', [u'Test Post 1', u'Question?', 1])
DEBUG:peewee:('RELEASE SAVEPOINT "s86e3fbb27555458bb1c03c846eabf2e6";', None)
INFO:__main__:Creating post 2
DEBUG:peewee:('SAVEPOINT "sb2f8f9f353cd4e0994a2515d4742e5cc";', None)
DEBUG:peewee:('SELECT "t1"."id", "t1"."name" FROM "forum" AS "t1" WHERE ("t1"."name" = ?) LIMIT ? OFFSET ?', [u'Bar Forum', 1, 0])
DEBUG:peewee:('SAVEPOINT "s0c3e9fc230d349daa357b53735d23382";', None)
DEBUG:peewee:('INSERT INTO "forum" ("name") VALUES (?)', [u'Bar Forum'])
DEBUG:peewee:('RELEASE SAVEPOINT "s0c3e9fc230d349daa357b53735d23382";', None)
DEBUG:peewee:('SELECT "t1"."id", "t1"."name", "t1"."forum_id" FROM "thread" AS "t1" WHERE (("t1"."name" = ?) AND ("t1"."forum_id" = ?)) LIMIT ? OFFSET ?', [u'Bar Thread One', 2, 1, 0])
DEBUG:peewee:('SAVEPOINT "sa0af313a8f544b4cb9eb4908c97334ab";', None)
DEBUG:peewee:('INSERT INTO "thread" ("name", "forum_id") VALUES (?, ?)', [u'Bar Thread One', 2])
DEBUG:peewee:('RELEASE SAVEPOINT "sa0af313a8f544b4cb9eb4908c97334ab";', None)
DEBUG:peewee:('INSERT INTO "post" ("title", "body", "thread_id") VALUES (?, ?, ?)', [u'Off-Topic', u'Rant, Rave...', 2])
DEBUG:peewee:('RELEASE SAVEPOINT "sb2f8f9f353cd4e0994a2515d4742e5cc";', None)
INFO:__main__:Creating post 3
DEBUG:peewee:('SAVEPOINT "s03d90b12912e49028a73c6cf390b1659";', None)
DEBUG:peewee:('SELECT "t1"."id", "t1"."name" FROM "forum" AS "t1" WHERE ("t1"."name" = ?) LIMIT ? OFFSET ?', [u'Foo Forum', 1, 0])
DEBUG:peewee:('SELECT "t1"."id", "t1"."name", "t1"."forum_id" FROM "thread" AS "t1" WHERE (("t1"."name" = ?) AND ("t1"."forum_id" = ?)) LIMIT ? OFFSET ?', [u'Foo Thread One', 1, 1, 0])
DEBUG:peewee:('INSERT INTO "post" ("title", "body", "thread_id") VALUES (?, ?, ?)', [u'Re: Test Post 1', u'Answer.', 1])
DEBUG:peewee:('RELEASE SAVEPOINT "s03d90b12912e49028a73c6cf390b1659";', None)
INFO:__main__:Done creating all posts
INFO:__main__:Populate returned
```

I think that one source of my confusion is that APSWDatabase executes the transaction BEGIN and COMMIT statements directly, bypassing the normal logging that execute_sql does. So it's doing what it should, but I can't tell that from looking at the logs.

https://github.com/coleifer/peewee/blob/master/playhouse/apsw_ext.py#L106

> I think that one source of my confusion is that APSWDatabase executes the transaction BEGIN and COMMIT statements directly, bypassing the normal logging that execute_sql does. So it's doing what it should, but I can't tell that from looking at the logs.

Yes that is the reason you weren't seeing `begin` or `commit` being logged with apsw.