Project

General

Profile

Bug #100990

dataviz: save avec force_update error (DatabaseError: Forced update did not affect any rows.)

Added by Sentry Io 30 days ago. Updated 7 days ago.

Status:
Solution proposée
Priority:
Normal
Target version:
-
Start date:
20 January 2025
Due date:
% Done:

0%

Estimated time:
Patch proposed:
No
Planning:
No

Description

https://sentry.entrouvert.org/entrouvert/publik/issues/136774/

DatabaseError: Forced update did not affect any rows.
(47 additional frame(s) were not displayed)
...
  File "combo/apps/dataviz/forms.py", line 473, in update_backoffice_filter_choices
    filters_cell.save(force_update=True)
  File "combo/data/models.py", line 1080, in save
    return super().save(*args, **kwargs)
  File "django/db/models/base.py", line 814, in save
    self.save_base(
  File "django/db/models/base.py", line 877, in save_base
    updated = self._save_table(
  File "django/db/models/base.py", line 994, in _save_table
    raise DatabaseError("Forced update did not affect any rows.")

Related issues

Related to Combo - Bug #97672: dataviz, IntegrityError: duplicate key value violates unique constraint "dataviz_chartfilterscell_pkey"Solution déployée28 October 2024

Actions

History

#1

Updated by Lauréline Guérin 30 days ago

  • Project changed from Suivi des traces to Combo
#2

Updated by Lauréline Guérin 30 days ago

  • Related to Bug #97672: dataviz, IntegrityError: duplicate key value violates unique constraint "dataviz_chartfilterscell_pkey" added
#3

Updated by Valentin Deniaud 30 days ago

  • Assignee set to Valentin Deniaud

Mon patch sans comprendre du ticket lié ne fonctionne pas pour éviter la trace, dommage

#4

Updated by Benjamin Dauvergne (en congé) 15 days ago

Actuellement la cellule 104 n'est plus là, on a donc eu une race condition entre sa lecture et le .save() et dans le code de save si l'update échoue, c'est converti automatiquement en insert:

        if pk_set and not force_insert:
            base_qs = cls._base_manager.using(using)
            values = [
                (
                    f,
                    None,
                    (getattr(self, f.attname) if raw else f.pre_save(self, False)),
                )
                for f in non_pks
            ]
            forced_update = update_fields or force_update
            updated = self._do_update(
                base_qs, using, pk_val, values, update_fields, forced_update
            )
            if force_update and not updated:
                raise DatabaseError("Forced update did not affect any rows.")
            if update_fields and not updated:
                raise DatabaseError("Save with update_fields did not affect any rows.")
        if not updated:

Ici ce qui est spécial c'est que dans une chemin de code qui ne fait que du rendu on a des écritures en base, c'est casse gueule sans transaction. Pour être certain que ça passe tu peux mettre un with atomic(savepoint=False): autour du code qui initialise le formulaire dans get_extra_context() le .save() ayant lieu dans __init__(). Sinon convertir le .save() en Class.objects.filter(pk=instance.pk).update(....) qui pourra foirer en silence.

#5

Updated by Benjamin Dauvergne (en congé) 15 days ago

Ce qui n'est pas bien clair pour moi à ce stade c'est comment l'id 104 a pu être réutilisé entre la trace initiale https://sentry.entrouvert.org/entrouvert/publik/issues/134543/ du ticket https://dev.entrouvert.org/issues/97672#note-2 et celle ci.

Je vais vérifier la piste évoqué dans le précédent ticket sur les triggers:

There are some rare cases where the database doesn’t report that a row was updated even if the database contains a row for the object’s primary key value. An example is the PostgreSQL ON UPDATE trigger which returns NULL.

Peut-être que ce n'est pas une race condition entre un DELETE et un UPDATE finalement.

#6

Updated by Benjamin Dauvergne (en congé) 15 days ago

Bon ça s'obscurcit pour moi aussi, seule contournement sûr trouvé, ajouter select_on_save = True à Meta1, ça garantit l'utilisation d'un algo différent pour save() datant de Django 1.6 (https://code.djangoproject.com/ticket/16649) adapté depuis (https://code.djangoproject.com/ticket/22967) au lieu de

UPDATE
if not UPDATE:
   INSERT

Ça fait
SELECT
if SELECT:
   UPDATE
   SELECT
   return SELECT
else:
   INSERT

Dans le deuxième cas si le UPDATE ne retourne rien (sans qu'on sache pourquoi pour l'instant, pas de TRIGGER RETURNING NULL trouvé en base sur cette table) ça passera quand même.

1 https://docs.djangoproject.com/en/5.1/ref/models/options/#django.db.models.Options.select_on_save

#7

Updated by Benjamin Dauvergne (en congé) 15 days ago

J'aurai bien testé aussi un update_fields=['filters'] (sans le force_update=True) aussi mais le bug est tellement rare...

Aussi en base on voit des soucis de lock au même moment sur la table indiquée sans que je sache comment ça pourrait produire un UPDATE retournant zéro lignes:

2025-01-20 07:37:15 CET [1623061]: db=combo,user=combo,app=agents_ville_chambery_test_entrouvert_org,client=192.168.1.11 LOG:  disconnection: session time: 0:02:22.082 user=combo database=combo host=192.168.1.11 port=46738
2025-01-20 07:39:48 CET [1626442]: db=combo,user=combo,app=agents_ville_chambery_test_entrouvert_org,client=192.168.1.11 LOG:  process 1626442 still waiting for ShareLock on transaction 660377197 after 1000.084 ms
2025-01-20 07:39:48 CET [1626442]: db=combo,user=combo,app=agents_ville_chambery_test_entrouvert_org,client=192.168.1.11 DETAIL:  Process holding the lock: 1626402. Wait queue: 1626442.
2025-01-20 07:39:48 CET [1626442]: db=combo,user=combo,app=agents_ville_chambery_test_entrouvert_org,client=192.168.1.11 CONTEXT:  while updating tuple (0,8) in relation "dataviz_chartfilterscell" 
2025-01-20 07:39:48 CET [1626442]: db=combo,user=combo,app=agents_ville_chambery_test_entrouvert_org,client=192.168.1.11 STATEMENT:  UPDATE "dataviz_chartfilterscell" SET "uuid" = 'ec9a58ed-649d-4c9a-8486-788769a8c0a1'::uuid, "page_id" = 158, "placeholder" = 'sidebar', "order" = 12, "slug" = '', "extra_css_class" = '', "template_name" = NULL, "condition" = '', "public" = true, "restricted_to_unlogged" = false, "last_update_timestamp" = '2025-01-20T06:39:47.983284+00:00'::timestamptz, "filters" = '{"channel": {"label": "Canal", "enabled": true}}' WHERE "dataviz_chartfilterscell"."id" = 105
2025-01-20 07:39:49 CET [1626442]: db=combo,user=combo,app=agents_ville_chambery_test_entrouvert_org,client=192.168.1.11 LOG:  process 1626442 still waiting for ShareLock on transaction 660377197 after 1059.279 ms
2025-01-20 07:39:49 CET [1626442]: db=combo,user=combo,app=agents_ville_chambery_test_entrouvert_org,client=192.168.1.11 DETAIL:  Process holding the lock: 1626402. Wait queue: 1626442.
2025-01-20 07:39:49 CET [1626442]: db=combo,user=combo,app=agents_ville_chambery_test_entrouvert_org,client=192.168.1.11 CONTEXT:  while updating tuple (0,8) in relation "dataviz_chartfilterscell" 
2025-01-20 07:39:49 CET [1626442]: db=combo,user=combo,app=agents_ville_chambery_test_entrouvert_org,client=192.168.1.11 STATEMENT:  UPDATE "dataviz_chartfilterscell" SET "uuid" = 'ec9a58ed-649d-4c9a-8486-788769a8c0a1'::uuid, "page_id" = 158, "placeholder" = 'sidebar', "order" = 12, "slug" = '', "extra_css_class" = '', "template_name" = NULL, "condition" = '', "public" = true, "restricted_to_unlogged" = false, "last_update_timestamp" = '2025-01-20T06:39:47.983284+00:00'::timestamptz, "filters" = '{"channel": {"label": "Canal", "enabled": true}}' WHERE "dataviz_chartfilterscell"."id" = 105
2025-01-20 07:39:49 CET [1626449]: db=combo,user=combo,app=agents_ville_chambery_test_entrouvert_org,client=192.168.1.11 LOG:  process 1626449 still waiting for ExclusiveLock on tuple (0,8) of relation 1171258 of database 17128 after 1000.059 ms
2025-01-20 07:39:49 CET [1626449]: db=combo,user=combo,app=agents_ville_chambery_test_entrouvert_org,client=192.168.1.11 DETAIL:  Process holding the lock: 1626442. Wait queue: 1626449.
2025-01-20 07:39:49 CET [1626449]: db=combo,user=combo,app=agents_ville_chambery_test_entrouvert_org,client=192.168.1.11 STATEMENT:  UPDATE "dataviz_chartfilterscell" SET "uuid" = 'ec9a58ed-649d-4c9a-8486-788769a8c0a1'::uuid, "page_id" = 158, "placeholder" = 'sidebar', "order" = 12, "slug" = '', "extra_css_class" = '', "template_name" = NULL, "condition" = '', "public" = true, "restricted_to_unlogged" = false, "last_update_timestamp" = '2025-01-20T06:39:48.469510+00:00'::timestamptz, "filters" = '{"channel": {"label": "Canal", "enabled": true}}' WHERE "dataviz_chartfilterscell"."id" = 105
2025-01-20 07:39:49 CET [1626449]: db=combo,user=combo,app=agents_ville_chambery_test_entrouvert_org,client=192.168.1.11 LOG:  process 1626449 still waiting for ExclusiveLock on tuple (0,8) of relation 1171258 of database 17128 after 1330.397 ms
2025-01-20 07:39:49 CET [1626449]: db=combo,user=combo,app=agents_ville_chambery_test_entrouvert_org,client=192.168.1.11 DETAIL:  Process holding the lock: 1626442. Wait queue: 1626449.
2025-01-20 07:39:49 CET [1626449]: db=combo,user=combo,app=agents_ville_chambery_test_entrouvert_org,client=192.168.1.11 STATEMENT:  UPDATE "dataviz_chartfilterscell" SET "uuid" = 'ec9a58ed-649d-4c9a-8486-788769a8c0a1'::uuid, "page_id" = 158, "placeholder" = 'sidebar', "order" = 12, "slug" = '', "extra_css_class" = '', "template_name" = NULL, "condition" = '', "public" = true, "restricted_to_unlogged" = false, "last_update_timestamp" = '2025-01-20T06:39:48.469510+00:00'::timestamptz, "filters" = '{"channel": {"label": "Canal", "enabled": true}}' WHERE "dataviz_chartfilterscell"."id" = 105
2025-01-20 07:40:16 CET [1626442]: db=combo,user=combo,app=agents_ville_chambery_test_entrouvert_org,client=192.168.1.11 LOG:  process 1626442 acquired ShareLock on transaction 660377197 after 28656.143 ms
2025-01-20 07:40:16 CET [1626442]: db=combo,user=combo,app=agents_ville_chambery_test_entrouvert_org,client=192.168.1.11 CONTEXT:  while updating tuple (0,8) in relation "dataviz_chartfilterscell" 
2025-01-20 07:40:16 CET [1626442]: db=combo,user=combo,app=agents_ville_chambery_test_entrouvert_org,client=192.168.1.11 STATEMENT:  UPDATE "dataviz_chartfilterscell" SET "uuid" = 'ec9a58ed-649d-4c9a-8486-788769a8c0a1'::uuid, "page_id" = 158, "placeholder" = 'sidebar', "order" = 12, "slug" = '', "extra_css_class" = '', "template_name" = NULL, "condition" = '', "public" = true, "restricted_to_unlogged" = false, "last_update_timestamp" = '2025-01-20T06:39:47.983284+00:00'::timestamptz, "filters" = '{"channel": {"label": "Canal", "enabled": true}}' WHERE "dataviz_chartfilterscell"."id" = 105
2025-01-20 07:40:16 CET [1626449]: db=combo,user=combo,app=agents_ville_chambery_test_entrouvert_org,client=192.168.1.11 LOG:  process 1626449 acquired ExclusiveLock on tuple (0,8) of relation 1171258 of database 17128 after 28169.812 ms
2025-01-20 07:40:16 CET [1626449]: db=combo,user=combo,app=agents_ville_chambery_test_entrouvert_org,client=192.168.1.11 STATEMENT:  UPDATE "dataviz_chartfilterscell" SET "uuid" = 'ec9a58ed-649d-4c9a-8486-788769a8c0a1'::uuid, "page_id" = 158, "placeholder" = 'sidebar', "order" = 12, "slug" = '', "extra_css_class" = '', "template_name" = NULL, "condition" = '', "public" = true, "restricted_to_unlogged" = false, "last_update_timestamp" = '2025-01-20T06:39:48.469510+00:00'::timestamptz, "filters" = '{"channel": {"label": "Canal", "enabled": true}}' WHERE "dataviz_chartfilterscell"."id" = 105
2025-01-20 07:40:16 CET [1626442]: db=combo,user=combo,app=agents_ville_chambery_test_entrouvert_org,client=192.168.1.11 LOG:  duration: 28658.668 ms  statement: UPDATE "dataviz_chartfilterscell" SET "uuid" = 'ec9a58ed-649d-4c9a-8486-788769a8c0a1'::uuid, "page_id" = 158, "placeholder" = 'sidebar', "order" = 12, "slug" = '', "extra_css_class" = '', "template_name" = NULL, "condition" = '', "public" = true, "restricted_to_unlogged" = false, "last_update_timestamp" = '2025-01-20T06:39:47.983284+00:00'::timestamptz, "filters" = '{"channel": {"label": "Canal", "enabled": true}}' WHERE "dataviz_chartfilterscell"."id" = 105
2025-01-20 07:40:16 CET [1626449]: db=combo,user=combo,app=agents_ville_chambery_test_entrouvert_org,client=192.168.1.11 LOG:  duration: 28172.966 ms  statement: UPDATE "dataviz_chartfilterscell" SET "uuid" = 'ec9a58ed-649d-4c9a-8486-788769a8c0a1'::uuid, "page_id" = 158, "placeholder" = 'sidebar', "order" = 12, "slug" = '', "extra_css_class" = '', "template_name" = NULL, "condition" = '', "public" = true, "restricted_to_unlogged" = false, "last_update_timestamp" = '2025-01-20T06:39:48.469510+00:00'::timestamptz, "filters" = '{"channel": {"label": "Canal", "enabled": true}}' WHERE "dataviz_chartfilterscell"."id" = 105

#8

Updated by Benjamin Dauvergne (en congé) 15 days ago

Aussi ce save() dans un Form.__init__() génère beaucoup d'update inutile si les filtres ne changent pas à chaque fois et donc beaucoup de contention sur un verrou RowExclusiveLock, ça vaut peut-être la peine de rendre l'update conditionelle (en python) en générant la nouvelle valeur de filters et la comparant à l'ancienne et ne sauver que si cela a changé.

#9

Updated by Robot Gitea 7 days ago

  • Status changed from Nouveau to En cours

Valentin Deniaud (vdeniaud) a ouvert une pull request sur Gitea concernant cette demande :

#10

Updated by Robot Gitea 7 days ago

  • Status changed from En cours to Solution proposée

Also available in: Atom PDF