Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

db.atomic decorator is not a thread-safe #2709

Closed
delatars opened this issue Apr 19, 2023 · 3 comments
Closed

db.atomic decorator is not a thread-safe #2709

delatars opened this issue Apr 19, 2023 · 3 comments

Comments

@delatars
Copy link

Hello!
peewee: 3.15.4
python: 3.10.8

Using db.atomic as decorator is not a thread-safe.
The following example is showing that behaviour.

import logging
import random
import uuid
from concurrent.futures import ThreadPoolExecutor
from time import sleep

import peewee

from playhouse.pool import PooledPostgresqlExtDatabase


db = PooledPostgresqlExtDatabase(
    database='test',
    user='postgres',
    password='postgres',
    host='localhost',
)
logging.basicConfig(
    level=logging.DEBUG,
    format='[%(asctime)s] %(levelname)s [%(thread)s] %(message)s',
    datefmt='%Y-%m-%d %H:%M:%S',
)


class User(peewee.Model):

    class Meta:
        database = db
        table_name = 'users'

    name = peewee.TextField()


@db.atomic()
def get_first():
    sleep(random.randint(1, 3))
    return User.select().first()


def main(n):
    print(f'task {n}: start')
    with db.atomic():
        User.insert(name=uuid.uuid4().hex).execute()
        get_first()


with ThreadPoolExecutor(max_workers=5) as worker:
    worker.map(main, range(5))

app logs

[2023-04-19 13:59:56] DEBUG [6174699520] No connection available in pool.
[2023-04-19 13:59:56] DEBUG [6174699520] Created new connection 4365525936.
[2023-04-19 13:59:56] DEBUG [6174699520] ('INSERT INTO "users" ("name") VALUES (%s) RETURNING "users"."id"', ['erika16'])
[2023-04-19 13:59:56] DEBUG [6191525888] No connection available in pool.
[2023-04-19 13:59:56] DEBUG [6191525888] Created new connection 4365526608.
[2023-04-19 13:59:56] DEBUG [6191525888] ('INSERT INTO "users" ("name") VALUES (%s) RETURNING "users"."id"', ['qfritz'])
[2023-04-19 13:59:56] DEBUG [6208352256] No connection available in pool.
[2023-04-19 13:59:56] DEBUG [6174699520] ('SAVEPOINT "s36f6b1b9c9964d338b76086917abfa2c";', None)
[2023-04-19 13:59:56] DEBUG [6191525888] ('SAVEPOINT "sf48e71a842874f81989e4b29ebb93c5b";', None)
[2023-04-19 13:59:56] DEBUG [6208352256] Created new connection 4365526944.
[2023-04-19 13:59:56] DEBUG [6208352256] ('INSERT INTO "users" ("name") VALUES (%s) RETURNING "users"."id"', ['paulanderson'])
[2023-04-19 13:59:56] DEBUG [6225178624] No connection available in pool.
[2023-04-19 13:59:56] DEBUG [6225178624] Created new connection 4365527280.
[2023-04-19 13:59:56] DEBUG [6225178624] ('INSERT INTO "users" ("name") VALUES (%s) RETURNING "users"."id"', ['patricia09'])
[2023-04-19 13:59:56] DEBUG [6242004992] No connection available in pool.
[2023-04-19 13:59:56] DEBUG [6225178624] ('SAVEPOINT "s4ce9c8529df342a9ac71c47196be2567";', None)
[2023-04-19 13:59:56] DEBUG [6242004992] Created new connection 4365527616.
[2023-04-19 13:59:56] DEBUG [6242004992] ('INSERT INTO "users" ("name") VALUES (%s) RETURNING "users"."id"', ['christina08'])
[2023-04-19 13:59:57] DEBUG [6208352256] ('SAVEPOINT "s33981849fd6345f69f7365c8279e4472";', None)
[2023-04-19 13:59:57] DEBUG [6242004992] ('SAVEPOINT "s97756b77a9264a9cbf194afde4f9e546";', None)
[2023-04-19 13:59:57] DEBUG [6174699520] ('SELECT "t1"."id", "t1"."name" FROM "users" AS "t1" LIMIT %s', [1])
[2023-04-19 13:59:57] DEBUG [6174699520] ('RELEASE SAVEPOINT "s97756b77a9264a9cbf194afde4f9e546";', None)
[2023-04-19 13:59:57] DEBUG [6174699520] ('ROLLBACK TO SAVEPOINT "s97756b77a9264a9cbf194afde4f9e546";', None)
[2023-04-19 13:59:57] DEBUG [6191525888] ('SELECT "t1"."id", "t1"."name" FROM "users" AS "t1" LIMIT %s', [1])
[2023-04-19 13:59:57] DEBUG [6191525888] ('RELEASE SAVEPOINT "s97756b77a9264a9cbf194afde4f9e546";', None)
[2023-04-19 13:59:57] DEBUG [6191525888] ('ROLLBACK TO SAVEPOINT "s97756b77a9264a9cbf194afde4f9e546";', None)
[2023-04-19 13:59:58] DEBUG [6208352256] ('SELECT "t1"."id", "t1"."name" FROM "users" AS "t1" LIMIT %s', [1])
[2023-04-19 13:59:58] DEBUG [6208352256] ('RELEASE SAVEPOINT "s97756b77a9264a9cbf194afde4f9e546";', None)
[2023-04-19 13:59:58] DEBUG [6208352256] ('ROLLBACK TO SAVEPOINT "s97756b77a9264a9cbf194afde4f9e546";', None)
[2023-04-19 13:59:58] DEBUG [6242004992] ('SELECT "t1"."id", "t1"."name" FROM "users" AS "t1" LIMIT %s', [1])
[2023-04-19 13:59:58] DEBUG [6242004992] ('RELEASE SAVEPOINT "s97756b77a9264a9cbf194afde4f9e546";', None)
[2023-04-19 13:59:59] DEBUG [6225178624] ('SELECT "t1"."id", "t1"."name" FROM "users" AS "t1" LIMIT %s', [1])
[2023-04-19 13:59:59] DEBUG [6225178624] ('RELEASE SAVEPOINT "s97756b77a9264a9cbf194afde4f9e546";', None)
[2023-04-19 13:59:59] DEBUG [6225178624] ('ROLLBACK TO SAVEPOINT "s97756b77a9264a9cbf194afde4f9e546";', None)

In the logs above, we're see, that threads are trying to release savepoint with an id it did not create.

postgres logs:

2023-04-19 10:59:56.522 UTC [61057] LOG:  statement: BEGIN
2023-04-19 10:59:56.543 UTC [61057] LOG:  duration: 23.928 ms
2023-04-19 10:59:56.549 UTC [61057] LOG:  statement: INSERT INTO "users" ("name") VALUES ('erika16') RETURNING "users"."id"
2023-04-19 10:59:56.615 UTC [61057] LOG:  duration: 68.462 ms
2023-04-19 10:59:56.626 UTC [61059] LOG:  statement: BEGIN
2023-04-19 10:59:56.630 UTC [61059] LOG:  duration: 6.580 ms
2023-04-19 10:59:56.636 UTC [61059] LOG:  statement: INSERT INTO "users" ("name") VALUES ('qfritz') RETURNING "users"."id"
2023-04-19 10:59:56.637 UTC [61057] LOG:  statement: SAVEPOINT "s36f6b1b9c9964d338b76086917abfa2c";
2023-04-19 10:59:56.637 UTC [61057] LOG:  duration: 0.593 ms
2023-04-19 10:59:56.678 UTC [61059] LOG:  duration: 42.479 ms
2023-04-19 10:59:56.689 UTC [61059] LOG:  statement: SAVEPOINT "sf48e71a842874f81989e4b29ebb93c5b";
2023-04-19 10:59:56.691 UTC [61059] LOG:  duration: 1.423 ms
2023-04-19 10:59:56.728 UTC [61061] LOG:  statement: BEGIN
2023-04-19 10:59:56.732 UTC [61061] LOG:  duration: 8.113 ms
2023-04-19 10:59:56.735 UTC [61061] LOG:  statement: INSERT INTO "users" ("name") VALUES ('paulanderson') RETURNING "users"."id"
2023-04-19 10:59:56.819 UTC [61063] LOG:  statement: BEGIN
2023-04-19 10:59:56.824 UTC [61063] LOG:  duration: 6.820 ms
2023-04-19 10:59:56.828 UTC [61063] LOG:  statement: INSERT INTO "users" ("name") VALUES ('patricia09') RETURNING "users"."id"
2023-04-19 10:59:56.922 UTC [61063] LOG:  duration: 94.511 ms
2023-04-19 10:59:56.928 UTC [61063] LOG:  statement: SAVEPOINT "s4ce9c8529df342a9ac71c47196be2567";
2023-04-19 10:59:56.929 UTC [61063] LOG:  duration: 0.893 ms
2023-04-19 10:59:56.981 UTC [61065] LOG:  statement: BEGIN
2023-04-19 10:59:56.984 UTC [61065] LOG:  duration: 5.307 ms
2023-04-19 10:59:56.987 UTC [61065] LOG:  statement: INSERT INTO "users" ("name") VALUES ('christina08') RETURNING "users"."id"
2023-04-19 10:59:57.009 UTC [61061] LOG:  duration: 274.434 ms
2023-04-19 10:59:57.015 UTC [61061] LOG:  statement: SAVEPOINT "s33981849fd6345f69f7365c8279e4472";
2023-04-19 10:59:57.015 UTC [61061] LOG:  duration: 0.838 ms
2023-04-19 10:59:57.219 UTC [61065] LOG:  duration: 232.845 ms
2023-04-19 10:59:57.222 UTC [61065] LOG:  statement: SAVEPOINT "s97756b77a9264a9cbf194afde4f9e546";
2023-04-19 10:59:57.222 UTC [61065] LOG:  duration: 0.481 ms
2023-04-19 10:59:57.644 UTC [61057] LOG:  statement: SELECT "t1"."id", "t1"."name" FROM "users" AS "t1" LIMIT 1
2023-04-19 10:59:57.657 UTC [61057] LOG:  duration: 13.231 ms
2023-04-19 10:59:57.661 UTC [61057] LOG:  statement: RELEASE SAVEPOINT "s97756b77a9264a9cbf194afde4f9e546";
2023-04-19 10:59:57.662 UTC [61057] ERROR:  savepoint "s97756b77a9264a9cbf194afde4f9e546" does not exist
2023-04-19 10:59:57.662 UTC [61057] STATEMENT:  RELEASE SAVEPOINT "s97756b77a9264a9cbf194afde4f9e546";
2023-04-19 10:59:57.672 UTC [61057] LOG:  statement: ROLLBACK TO SAVEPOINT "s97756b77a9264a9cbf194afde4f9e546";
2023-04-19 10:59:57.673 UTC [61057] ERROR:  savepoint "s97756b77a9264a9cbf194afde4f9e546" does not exist
2023-04-19 10:59:57.673 UTC [61057] STATEMENT:  ROLLBACK TO SAVEPOINT "s97756b77a9264a9cbf194afde4f9e546";
2023-04-19 10:59:57.677 UTC [61057] LOG:  statement: ROLLBACK
2023-04-19 10:59:57.684 UTC [61057] LOG:  duration: 6.259 ms
2023-04-19 10:59:57.695 UTC [61059] LOG:  statement: SELECT "t1"."id", "t1"."name" FROM "users" AS "t1" LIMIT 1
2023-04-19 10:59:57.721 UTC [61059] LOG:  duration: 26.199 ms
2023-04-19 10:59:57.724 UTC [61059] LOG:  statement: RELEASE SAVEPOINT "s97756b77a9264a9cbf194afde4f9e546";
2023-04-19 10:59:57.726 UTC [61059] ERROR:  savepoint "s97756b77a9264a9cbf194afde4f9e546" does not exist
2023-04-19 10:59:57.726 UTC [61059] STATEMENT:  RELEASE SAVEPOINT "s97756b77a9264a9cbf194afde4f9e546";
2023-04-19 10:59:57.733 UTC [61059] LOG:  statement: ROLLBACK TO SAVEPOINT "s97756b77a9264a9cbf194afde4f9e546";
2023-04-19 10:59:57.734 UTC [61059] ERROR:  savepoint "s97756b77a9264a9cbf194afde4f9e546" does not exist
2023-04-19 10:59:57.734 UTC [61059] STATEMENT:  ROLLBACK TO SAVEPOINT "s97756b77a9264a9cbf194afde4f9e546";
2023-04-19 10:59:57.741 UTC [61059] LOG:  statement: ROLLBACK
2023-04-19 10:59:57.778 UTC [61059] LOG:  duration: 37.320 ms
2023-04-19 10:59:58.023 UTC [61061] LOG:  statement: SELECT "t1"."id", "t1"."name" FROM "users" AS "t1" LIMIT 1
2023-04-19 10:59:58.041 UTC [61061] LOG:  duration: 18.985 ms
2023-04-19 10:59:58.045 UTC [61061] LOG:  statement: RELEASE SAVEPOINT "s97756b77a9264a9cbf194afde4f9e546";
2023-04-19 10:59:58.046 UTC [61061] ERROR:  savepoint "s97756b77a9264a9cbf194afde4f9e546" does not exist
2023-04-19 10:59:58.046 UTC [61061] STATEMENT:  RELEASE SAVEPOINT "s97756b77a9264a9cbf194afde4f9e546";
2023-04-19 10:59:58.050 UTC [61061] LOG:  statement: ROLLBACK TO SAVEPOINT "s97756b77a9264a9cbf194afde4f9e546";
2023-04-19 10:59:58.051 UTC [61061] ERROR:  savepoint "s97756b77a9264a9cbf194afde4f9e546" does not exist
2023-04-19 10:59:58.051 UTC [61061] STATEMENT:  ROLLBACK TO SAVEPOINT "s97756b77a9264a9cbf194afde4f9e546";
2023-04-19 10:59:58.054 UTC [61061] LOG:  statement: ROLLBACK
2023-04-19 10:59:58.071 UTC [61061] LOG:  duration: 17.898 ms
2023-04-19 10:59:58.228 UTC [61065] LOG:  statement: SELECT "t1"."id", "t1"."name" FROM "users" AS "t1" LIMIT 1
2023-04-19 10:59:58.247 UTC [61065] LOG:  duration: 20.065 ms
2023-04-19 10:59:58.249 UTC [61065] LOG:  statement: RELEASE SAVEPOINT "s97756b77a9264a9cbf194afde4f9e546";
2023-04-19 10:59:58.250 UTC [61065] LOG:  duration: 1.504 ms
2023-04-19 10:59:58.251 UTC [61065] LOG:  statement: COMMIT
2023-04-19 10:59:58.254 UTC [61065] LOG:  duration: 2.655 ms
2023-04-19 10:59:59.937 UTC [61063] LOG:  statement: SELECT "t1"."id", "t1"."name" FROM "users" AS "t1" LIMIT 1
2023-04-19 10:59:59.957 UTC [61063] LOG:  duration: 20.771 ms
2023-04-19 10:59:59.960 UTC [61063] LOG:  statement: RELEASE SAVEPOINT "s97756b77a9264a9cbf194afde4f9e546";
2023-04-19 10:59:59.961 UTC [61063] ERROR:  savepoint "s97756b77a9264a9cbf194afde4f9e546" does not exist
2023-04-19 10:59:59.961 UTC [61063] STATEMENT:  RELEASE SAVEPOINT "s97756b77a9264a9cbf194afde4f9e546";
2023-04-19 10:59:59.964 UTC [61063] LOG:  statement: ROLLBACK TO SAVEPOINT "s97756b77a9264a9cbf194afde4f9e546";
2023-04-19 10:59:59.964 UTC [61063] ERROR:  savepoint "s97756b77a9264a9cbf194afde4f9e546" does not exist
2023-04-19 10:59:59.964 UTC [61063] STATEMENT:  ROLLBACK TO SAVEPOINT "s97756b77a9264a9cbf194afde4f9e546";
2023-04-19 10:59:59.966 UTC [61063] LOG:  statement: ROLLBACK
2023-04-19 10:59:59.968 UTC [61063] LOG:  duration: 1.987 ms
@coleifer
Copy link
Owner

Yes you're quite right, thanks for finding this. The issue is down to the fact that a single instance is being created and reused/overwritten. I will figure out a fix. For now the workaround will need to be to use the context manager.

coleifer added a commit that referenced this issue Apr 19, 2023
@coleifer
Add regression test for #2709
9cabb4a 
Adds a new "slow_test" decorator and enables slow tests to be run during
CI.
@coleifer
Copy link
Owner

This should now be fixed.

@coleifer
Copy link
Owner

3.16.2 release contains this fix, thanks for the report this really needed to be fixed!

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@coleifer @delatars