Django-fr

Forum

  • Accueil
  • » Django-fr
  • » Crash silencieux systématique avec transaction.atomic()

#1 01-12-2014 13:27:39

Olivier Cortes
Membre
Inscription : 21-07-2016
Messages : 2

Crash silencieux systématique avec transaction.atomic()

Bonjour à tous,

[merci à tous ceux qui auront la patience de lire tout mon mail. Ma
gratitude vous enveloppe châleureusement en ces humides journées
d'hiver]

j'ai du code Django 1.6.8 où si j'active `transaction.commit()` autour
d'un simple bloc, une erreur se produit *systématiquement* quelque part
près de la BDD.

Mais je ne sais pas *quelle erreur*, car elle n'est pas remontée. Et
bien évidement, quand elle se produit et occasionne la fermeture de la
connexion à la base, tout le process plante à cause d'un
"InterfaceError: connection already closed".

Dans mon cas, c'est dans un worker celery avec gevent. Donc tout le
worker s'arrête, alors qu'il est censé gérer 100 tâches à la seconde, et
envoyer d'autres tâches en suivant à d'autres workers qui se retrouvent
au chomage, et forcément le gouvernement nous crée des platasses de lois
pour créer des jobs de merde, et… Ah non, c'est pas ici que je dois dire
ça. Au moins, la machine ne chauffe plus, mais autant dire que c'est pas
vraiment ce que je souhaite.

J'ai cherché un bon moment sur Gogogle, qui m'a donné finalement ça :

https://code.djangoproject.com/ticket/21202

C'était le bug parfait, presque exactement mon problème, mais Aymeric a
corrigé ce truc depuis plus d'un an, et tous mes petits pypis sont à
jour. J'ai le sentiment qu'il reste [peut-être au moins] un cas dans
lequel le problème se produit encore [à peu près pareil], puisque si je
retire le `transaction.atomic()`, je n'ai plus le "InterfaceError". De
temps j'ai un crash de type IntegrityError, justement celui que la doc
dit d'encadrer comme ça:

    try:
        with transaction.atomic():
            do_some_stuff()
    except IntegrityError:
        handle_exception()

Le truc c'est que quand je l'encadre pour le cas sur 10k où il se
produit, ben plus rien ne s'exécute et la connexion à la base est fermée
pour une raison inconnue (celle qui est la cause du pourquoi je vous
écris un mail de 5Ko, vous suivez ?).

J'ai réussi à isoler un endroit où ça pète :

https://github.com/1flow/1flow/blob/develop/oneflow/core/models/reldb/feed/rssatom.py#L581

Si je rajoute un "with transaction.atomic():" entre le try: et le
"new_article.add_original_data(…)", ben tout le worker s'arrête avec une
stacktrace comme http://dev.1flow.net/1flow/1flow/group/48838/ .

Mais je suis obligé d'attendre que celery essaie de tracer le résultat
de la tâche pour qu'il se rende comte que la connexion a été fermée
avant, et du coup plus personne ne sait pourquoi ça a eu lieu. atomic()
a bouffé l'exception.

Bref, je suis un peu dég'. Tout le bienfait de `transaction.atomic()`
part en fumée, et de temps en temps (une fois toutes les 1000 ou 10k
transactions), j'ai une tâche qui plante pour une vraie raison, et qui
forcément me plante mon worker puisque je n'ai pas d'atomic() pour me
protéger le call « comme il faut le faire que c'est écrit dans la doc,
mais RTFM, bordel™ ».

Alors avant d'ouvrir un bug en anglais qui sera wontfix parce que je
n'arriverai pas à reproduire mon problème en 10 lignes, je serai preneur
d'une idée, une piste, un truc à essayer, un retour d'expérience, qui
pourrait me lancer sur la voie de quelque chose que j'aurais oublié.

Si vous aimez les projets libres et que vous avez un peu de temps, ça
peut se faire autour d'une bière (ou d'un rouge, ou d'un jus de fruit,
ou d'un café) si vous êtes dans la région de bordeaux…

PS: une fois sur 1k ou 10K ça peut paraître peu, mais sur
http://1flow.io/ c'est environ toutes les 9h… Et comme on ne peut pas
encore redémarrer les workers de l'intérieur (cf.
http://stackoverflow.com/q/14447322/654755) j'en suis réduit à
redémarrer mes workers toutes les 6h automatiquement pendant les phases
où je ne pas veiller au grain, ce qui occasionne quelques tâches qui
partent à la trappe, et ainsi de suite. Bref, pendant ce temps, sentry,
lui, est bien nourri.

Allez a+ et merci à tous. Même si c'est pour envoyer une vanne, ça me
fera plaisir.

--
Olivier

Hors ligne

#2 01-12-2014 21:20:19

Olivier
Membre
Inscription : 21-07-2016
Messages : 8

Re : Crash silencieux systématique avec transaction.atomic()

Hello,
j'aurai bien fait une vanne sur "mais quelle hérésie une biere au pays
du rouge" mais bof

Par contre que disent les logs du SGBDR ? Quelle est-elle ? Oracle ?
Postgresql ?
Là, genre, paradoxalement, j'aurai plutôt conservé des connexions
persistantes (si elle ne le sont pas) et je me demande s'il n'y a
justement pas assez de cursors ouverts pour traiter toutes les demandes,
ce qui du coup, lorsqu'arrive le moment d'en traiter une,
qui n'a plus "sa place" ; lâche.
Mais avant de partir trop loin en conjecture, les logs seraient pratique.

cordialement.


Le 01/12/2014 13:27, Olivier Cortes a écrit :
> Bonjour à tous,
>
> [merci à tous ceux qui auront la patience de lire tout mon mail. Ma
> gratitude vous enveloppe châleureusement en ces humides journées
> d'hiver]
>
> j'ai du code Django 1.6.8 où si j'active `transaction.commit()` autour
> d'un simple bloc, une erreur se produit *systématiquement* quelque part
> près de la BDD.
>
> Mais je ne sais pas *quelle erreur*, car elle n'est pas remontée. Et
> bien évidement, quand elle se produit et occasionne la fermeture de la
> connexion à la base, tout le process plante à cause d'un
> "InterfaceError: connection already closed".
>
> Dans mon cas, c'est dans un worker celery avec gevent. Donc tout le
> worker s'arrête, alors qu'il est censé gérer 100 tâches à la seconde, et
> envoyer d'autres tâches en suivant à d'autres workers qui se retrouvent
> au chomage, et forcément le gouvernement nous crée des platasses de lois
> pour créer des jobs de merde, et… Ah non, c'est pas ici que je dois dire
> ça. Au moins, la machine ne chauffe plus, mais autant dire que c'est pas
> vraiment ce que je souhaite.
>
> J'ai cherché un bon moment sur Gogogle, qui m'a donné finalement ça :
>
> https://code.djangoproject.com/ticket/21202
>
> C'était le bug parfait, presque exactement mon problème, mais Aymeric a
> corrigé ce truc depuis plus d'un an, et tous mes petits pypis sont à
> jour. J'ai le sentiment qu'il reste [peut-être au moins] un cas dans
> lequel le problème se produit encore [à peu près pareil], puisque si je
> retire le `transaction.atomic()`, je n'ai plus le "InterfaceError". De
> temps j'ai un crash de type IntegrityError, justement celui que la doc
> dit d'encadrer comme ça:
>
>     try:
>         with transaction.atomic():
>             do_some_stuff()
>     except IntegrityError:
>         handle_exception()
>
> Le truc c'est que quand je l'encadre pour le cas sur 10k où il se
> produit, ben plus rien ne s'exécute et la connexion à la base est fermée
> pour une raison inconnue (celle qui est la cause du pourquoi je vous
> écris un mail de 5Ko, vous suivez ?).
>
> J'ai réussi à isoler un endroit où ça pète :
>
> https://github.com/1flow/1flow/blob/develop/oneflow/core/models/reldb/feed/rssatom.py#L581
>
> Si je rajoute un "with transaction.atomic():" entre le try: et le
> "new_article.add_original_data(…)", ben tout le worker s'arrête avec une
> stacktrace comme http://dev.1flow.net/1flow/1flow/group/48838/ .
>
> Mais je suis obligé d'attendre que celery essaie de tracer le résultat
> de la tâche pour qu'il se rende comte que la connexion a été fermée
> avant, et du coup plus personne ne sait pourquoi ça a eu lieu. atomic()
> a bouffé l'exception.
>
> Bref, je suis un peu dég'. Tout le bienfait de `transaction.atomic()`
> part en fumée, et de temps en temps (une fois toutes les 1000 ou 10k
> transactions), j'ai une tâche qui plante pour une vraie raison, et qui
> forcément me plante mon worker puisque je n'ai pas d'atomic() pour me
> protéger le call « comme il faut le faire que c'est écrit dans la doc,
> mais RTFM, bordel™ ».
>
> Alors avant d'ouvrir un bug en anglais qui sera wontfix parce que je
> n'arriverai pas à reproduire mon problème en 10 lignes, je serai preneur
> d'une idée, une piste, un truc à essayer, un retour d'expérience, qui
> pourrait me lancer sur la voie de quelque chose que j'aurais oublié.
>
> Si vous aimez les projets libres et que vous avez un peu de temps, ça
> peut se faire autour d'une bière (ou d'un rouge, ou d'un jus de fruit,
> ou d'un café) si vous êtes dans la région de bordeaux…
>
> PS: une fois sur 1k ou 10K ça peut paraître peu, mais sur
> http://1flow.io/ c'est environ toutes les 9h… Et comme on ne peut pas
> encore redémarrer les workers de l'intérieur (cf.
> http://stackoverflow.com/q/14447322/654755) j'en suis réduit à
> redémarrer mes workers toutes les 6h automatiquement pendant les phases
> où je ne pas veiller au grain, ce qui occasionne quelques tâches qui
> partent à la trappe, et ainsi de suite. Bref, pendant ce temps, sentry,
> lui, est bien nourri.
>
> Allez a+ et merci à tous. Même si c'est pour envoyer une vanne, ça me
> fera plaisir.
>
> --
> Olivier
>
> _______________________________________________
> django mailing list
> django _AT_ lists.afpy.org
> http://lists.afpy.org/mailman/listinfo/django
>

Hors ligne

#3 02-12-2014 00:35:16

Olivier Cortes
Membre
Inscription : 21-07-2016
Messages : 2

Re : Crash silencieux systématique avec transaction.atomic()

Re,

et merci pour la réponse.

Le lundi 01 décembre 2014 à 21:20 +0100, FoxMaSk a écrit :
> Hello,
> j'aurai bien fait une vanne sur "mais quelle hérésie une biere au pays
> du rouge" mais bof

ouais, je suis pas sectaire sur la boisson ;-)

> Par contre que disent les logs du SGBDR ? Quelle est-elle ? Oracle ?
> Postgresql ?

PostgreSQL 9.3 sur http://1flow.io/ et ma machine de dév, et 9.1 sur
d'autres instances. Le problème est commun aux deux versions, et se
produit avec DEBUG=True et DEBUG=False.

> Là, genre, paradoxalement, j'aurai plutôt conservé des connexions
> persistantes (si elle ne le sont pas) et je me demande s'il n'y a
> justement pas assez de cursors ouverts pour traiter toutes les demandes,
> ce qui du coup, lorsqu'arrive le moment d'en traiter une,
> qui n'a plus "sa place" ; lâche.

Les logs de PG n'indiquent rien de particulier au moment des problème,
ce qui est plutôt rassurant (ou pas) : lorsque les crash se produisent
avec transaction.atomic(), en fait il n'y a aucun problème particulier ;
j'en veux pour preuve que si je l'enlève, tout va bien (sauf un cas
d'erreur légitime sur X milliers de requêtes).

Les logs de PG ne sont pas vides, loin s'en faut, mais ils ne
contiennent que des :

2014-11-30 17:20:23 UTC ERROR:  duplicate key value violates unique
constraint "core_article_url_key"
2014-11-30 17:20:23 UTC DETAIL:  Key
(url)=(http://www.reddit.com/r/Music/comments/2nuhqs/megadeth_a_tout_le_monde_metal/) already exists.
2014-11-30 17:20:23 UTC STATEMENT:  INSERT INTO
"core_article" ("baseitem_ptr_id", "url", "comments_feed_url",
"url_absolute", "url_error", "is_orphaned", "ima
ge_url", "excerpt", "content", "content_type", "content_error",
"word_count") VALUES (16918397,
'http://www.reddit.com/r/Music/comments/2nuhqs/megadeth_a_tout_
le_monde_metal/', NULL, false, NULL, false, NULL, NULL, NULL, NULL,
NULL, NULL)

Qui sont les erreurs « normales » qui se produisent lors des
get_or_create() ou des update_or_create() (ah non mince lui c'est que
dans Django 1.7 ; en 1.6 je ne l'ai pas. Bien dommage d'ailleurs. Bref.)

> Mais avant de partir trop loin en conjecture, les logs seraient pratique.

Ben voilà. Je peux te mettre un log en accès FTP qq part, mais à
première vue c'est peine perdue. Sans compter qu'une journée de log,
c'est 200Mo minimum, à tendance 1.5Go… Si vraiment vous êtes demandeurs,
je ferai un extrait avant / après activation d'atomic().

Je viens de lire la doc des connexions persistantes, ça a l'air
alléchant. Pour l'instant, je n'ai rien changé (j'essaierai plutôt
demain, après une nuit de sommeil…).

J'avais monté le nombre de connexions parallèles à 256 dans
postgresql.conf pensant que ça pouvait éventuellement être lié (sans
grande motiv' parce que je vois pas pourquoi, en fait), mais ça n'a rien
changé. Faut dire qu'avec la configuration par défaut (100 connexions je
crois), ça passait très bien, et avec le bug que je rencontre sur
atomic(), quelle que soit la valeur, ça pète.

a+ et merci aux courageux qui lisent mes mails jusqu'au bout. Bonne
nuit,

--
Olivier
http://oliviercortes.com/
http://1flow.io/

Hors ligne

#4 02-12-2014 11:01:37

Olivier
Membre
Inscription : 21-07-2016
Messages : 8

Re : Crash silencieux systématique avec transaction.atomic()

Bonjour,

j'ai fait le tour de quelques trucs, voici ce que j'ai analysé

le mesage d'erreur est dû au fait que psycog, quand un pb survient,
tente de rollback avant de fermer la connexion, mais comme c'est déjà
fermé le rollback produit le message "connection already closed".

http://www.postgresql.org/message-id/CA+mi_8a3QoF5rLL0QFV2foU=KO+Cc4-jx3L=cZwS8kmUp+OhEw _AT_ mail.gmail.com


En relisant ce que vous mettez "en retirant atomic() ca marche avec des
erreurs" ; je suis perplexe ; pourquoi le framework, avec le
get_or_create() ferait le create s'il parvient à faire le get ? c'est
pas là le problème ? On dirait qu'il ne fait JAMAIS le get et plante
constamment sur le create quand le record est déjà dans la table.

Si vous solutionnez ce comportement, peut-etre que ca contenterait mieux
.atomic() ?

My 2 coins de noob assis dans le fond wink

Cordialement

Le 02.12.2014 00:35, Olivier Cortes a écrit :

> Re,
>
> et merci pour la réponse.
>
> Le lundi 01 décembre 2014 à 21:20 +0100, FoxMaSk a écrit :
>
>> Hello, j'aurai bien fait une vanne sur "mais quelle hérésie une biere au pays du rouge" mais bof
>
> ouais, je suis pas sectaire sur la boisson ;-)
>
>> Par contre que disent les logs du SGBDR ? Quelle est-elle ? Oracle ? Postgresql ?
>
> PostgreSQL 9.3 sur http://1flow.io/ [1] et ma machine de dév, et 9.1 sur
> d'autres instances. Le problème est commun aux deux versions, et se
> produit avec DEBUG=True et DEBUG=False.
>
>> Là, genre, paradoxalement, j'aurai plutôt conservé des connexions persistantes (si elle ne le sont pas) et je me demande s'il n'y a justement pas assez de cursors ouverts pour traiter toutes les demandes, ce qui du coup, lorsqu'arrive le moment d'en traiter une, qui n'a plus "sa place" ; lâche.
>
> Les logs de PG n'indiquent rien de particulier au moment des problème,
> ce qui est plutôt rassurant (ou pas) : lorsque les crash se produisent
> avec transaction.atomic(), en fait il n'y a aucun problème particulier ;
> j'en veux pour preuve que si je l'enlève, tout va bien (sauf un cas
> d'erreur légitime sur X milliers de requêtes).
>
> Les logs de PG ne sont pas vides, loin s'en faut, mais ils ne
> contiennent que des :
>
> 2014-11-30 17:20:23 UTC ERROR: duplicate key value violates unique
> constraint "core_article_url_key"
> 2014-11-30 17:20:23 UTC DETAIL: Key
> (url)=(http://www.reddit.com/r/Music/comments/2nuhqs/megadeth_a_tout_le_monde_metal/ [2]) already exists.
> 2014-11-30 17:20:23 UTC STATEMENT: INSERT INTO
> "core_article" ("baseitem_ptr_id", "url", "comments_feed_url",
> "url_absolute", "url_error", "is_orphaned", "ima
> ge_url", "excerpt", "content", "content_type", "content_error",
> "word_count") VALUES (16918397,
> 'http://www.reddit.com/r/Music/comments/2nuhqs/megadeth_a_tout_ [3]
> le_monde_metal/', NULL, false, NULL, false, NULL, NULL, NULL, NULL,
> NULL, NULL)
>
> Qui sont les erreurs « normales » qui se produisent lors des
> get_or_create() ou des update_or_create() (ah non mince lui c'est que
> dans Django 1.7 ; en 1.6 je ne l'ai pas. Bien dommage d'ailleurs. Bref.)
>
>> Mais avant de partir trop loin en conjecture, les logs seraient pratique.
>
> Ben voilà. Je peux te mettre un log en accès FTP qq part, mais à
> première vue c'est peine perdue. Sans compter qu'une journée de log,
> c'est 200Mo minimum, à tendance 1.5Go... Si vraiment vous êtes demandeurs,
> je ferai un extrait avant / après activation d'atomic().
>
> Je viens de lire la doc des connexions persistantes, ça a l'air
> alléchant. Pour l'instant, je n'ai rien changé (j'essaierai plutôt
> demain, après une nuit de sommeil...).
>
> J'avais monté le nombre de connexions parallèles à 256 dans
> postgresql.conf pensant que ça pouvait éventuellement être lié (sans
> grande motiv' parce que je vois pas pourquoi, en fait), mais ça n'a rien
> changé. Faut dire qu'avec la configuration par défaut (100 connexions je
> crois), ça passait très bien, et avec le bug que je rencontre sur
> atomic(), quelle que soit la valeur, ça pète.
>
> a+ et merci aux courageux qui lisent mes mails jusqu'au bout. Bonne
> nuit,
>
> --
> Olivier
> http://oliviercortes.com/ [4]
> http://1flow.io/ [1]
>
> _______________________________________________
> django mailing list
> django _AT_ lists.afpy.org
> http://lists.afpy.org/mailman/listinfo/django [5]


Links:
------
[1] http://1flow.io/
[2]
http://www.reddit.com/r/Music/comments/2nuhqs/megadeth_a_tout_le_monde_metal/
[3] http://www.reddit.com/r/Music/comments/2nuhqs/megadeth_a_tout_
[4] http://oliviercortes.com/
[5] http://lists.afpy.org/mailman/listinfo/django

Hors ligne

  • Accueil
  • » Django-fr
  • » Crash silencieux systématique avec transaction.atomic()

Pied de page des forums