Produits Entr'ouvert » Authentic 2

Bon je ne reproduis pas en local, je vais regarder plus en détails.

C'est peut-être une modification à la configuration du postgres local, il faudrait voir avec Guillaume et Pierre si quelque chose a été modifié de ce coté là, ensuite on pourra modifier le ratio. Le test est particulièrement agressif.

Ca bloque les build aujourd'hui, le test pourrait être adapté ? (moins agressif) ?

Sur le salon technique il est question de monter ce seuil à 50%. S’attendre à ce que moins de 10% des threads échouent ne me paraît pas trop agressif.

Ce qui se passe dans django est le QuerysSet._create_objects_from_params qui fait remonter une IntegrityError lorsque se produit le cas où la création de l’objet a échoué, et où dans un second temps sa tentative de récupération via une QuerySet nouvellement instanciée échoue elle aussi.

Je serais plutôt pour d’abord voir s’il y a eu des changements dans la configuration des accès concurrentiels à PG, je vais créer un ticket admin sys.

le test est fait sur quel base ? en local sur jenkins ?

je regarde les logs dans jenkins, est ce que ces erreurs sont "normales" (elles sont attendues et testés) ?

sinon on dirait qu'il n'arrive pas a purger la base à la fin.

*** /tmp/authentic-2447/pg_virtualenv.9jU6vC/log/postgresql-13-regress.log (last 100 lines) ***
2022-01-13 16:48:46.218 CET [335719] LOG:  démarrage de PostgreSQL 13.5 (Debian 13.5-0+deb11u1) on x86_64-pc-linux-gnu, compiled by gcc (Debian 10.2.1-6) 10.2.1 20210110, 64-bit
2022-01-13 16:48:46.218 CET [335719] LOG:  en écoute sur IPv6, adresse « ::1 », port 44441
2022-01-13 16:48:46.218 CET [335719] LOG:  en écoute sur IPv4, adresse « 127.0.0.1 », port 44441
2022-01-13 16:48:46.218 CET [335719] LOG:  écoute sur la socket Unix « /tmp/.s.PGSQL.44441 »
2022-01-13 16:48:46.220 CET [335720] LOG:  le système de bases de données a été arrêté à 2022-01-13 16:48:46 CET
2022-01-13 16:48:46.224 CET [335719] LOG:  le système de bases de données est prêt pour accepter les connexions
2022-01-13 16:56:50.363 CET [337978] jenkins@test_authentic2 ERREUR:  la valeur d'une clé dupliquée rompt la contrainte unique « authentic2_auth_oidc_oidcaccount_user_id_key »
2022-01-13 16:56:50.363 CET [337978] jenkins@test_authentic2 DÉTAIL:  La clé « (user_id)=(3311) » existe déjà.
2022-01-13 16:56:50.363 CET [337978] jenkins@test_authentic2 INSTRUCTION :  INSERT INTO "authentic2_auth_oidc_oidcaccount" ("created", "modified", "provider_id", "user_id", "sub") VALUES ('2022-01-13T15:56:50.362967+00:00'::timestamptz, '2022-01-13T15:56:50.362987+00:00'::timestamptz, 56, 3311, '4567') RETURNING "authentic2_auth_oidc_oidcaccount"."id" 
2022-01-13 17:01:29.731 CET [351208] jenkins@test_authentic2 ERREUR:  la valeur d'une clé dupliquée rompt la contrainte unique « authentic2_auth_fc_fcaccount_sub_order_a4c5049e_uniq »
2022-01-13 17:01:29.731 CET [351208] jenkins@test_authentic2 DÉTAIL:  La clé « (sub, "order")=(1234, 0) » existe déjà.
2022-01-13 17:01:29.731 CET [351208] jenkins@test_authentic2 INSTRUCTION :  INSERT INTO "authentic2_auth_fc_fcaccount" ("created", "modified", "user_id", "sub", "order", "token", "user_info") VALUES ('2022-01-13T16:01:29.731558+00:00'::timestamptz, '2022-01-13T16:01:29.731577+00:00'::timestamptz, 6169, '1234', 0, '{"access_token": "4da777b1-c473-4348-baf1-78fe34cfef82", "id_token": "eyJhbGciOiJIUzI1NiJ9.eyJhdWQiOiJ4eHgiLCJleHAiOjE2NDIwODk3NDksImlzcyI6Imh0dHBzOi8vZmNwLmludGVnMDEuZGV2LWZyYW5jZWNvbm5lY3QuZnIvIiwibm9uY2UiOiJfRHFRNHRwTjk2aGV3a01salRlaDZnT1NzYXc3amdzQjgwOVJzTnNIVTdZIiwic3ViIjoiMTIzNCJ9.v11na3qLxv_vzvRhaq2ec2hAg4zOKdjgGcSyzrCIXiM"}', '{"sub": "1234"}') RETURNING "authentic2_auth_fc_fcaccount"."id" 
2022-01-13 17:01:36.162 CET [351208] jenkins@test_authentic2 ERREUR:  la valeur d'une clé dupliquée rompt la contrainte unique « authentic2_auth_fc_fcaccount_user_id_order_9be8b543_uniq »
2022-01-13 17:01:36.162 CET [351208] jenkins@test_authentic2 DÉTAIL:  La clé « (user_id, "order")=(6181, 0) » existe déjà.
2022-01-13 17:01:36.162 CET [351208] jenkins@test_authentic2 INSTRUCTION :  INSERT INTO "authentic2_auth_fc_fcaccount" ("created", "modified", "user_id", "sub", "order", "token", "user_info") VALUES ('2022-01-13T16:01:36.161853+00:00'::timestamptz, '2022-01-13T16:01:36.161876+00:00'::timestamptz, 6181, '4567', 0, '{"access_token": "ecfe020f-cbe3-4779-b59c-959c6fcd854b", "id_token": "eyJhbGciOiJIUzI1NiJ9.eyJhdWQiOiJ4eHgiLCJlbWFpbCI6ImpvaG4uZG9lQGV4YW1wbGUuY29tIiwiZXhwIjoxNjQyMDg5NzU2LCJmYW1pbHlfbmFtZSI6IkZyXHUwMGU5ZFx1MDBlOXJpcXVlIiwiZ2l2ZW5fbmFtZSI6Ilx1MDE3OHVcdTAwZjFlIiwiaXNzIjoiaHR0cHM6Ly9mY3AuaW50ZWcwMS5kZXYtZnJhbmNlY29ubmVjdC5mci8iLCJub25jZSI6InFLM1kxcy1waTNHX1dOUGh2X0t1UC0wNTFUd2Q4aUNRbVJ4RTktdGZURTQiLCJzdWIiOiI0NTY3In0._1oRS3372FtuhS_z_bC6BSIjox6u7Xx8_60iw3s6j7c"}', '{"family_name": "Fr\u00e9d\u00e9rique", "given_name": "\u0178u\u00f1e", "email": "john.doe@example.com", "sub": "4567"}') RETURNING "authentic2_auth_fc_fcaccount"."id" 
2022-01-13 17:03:24.326 CET [364129] jenkins@test_authentic2 ERREUR:  n'a pas pu supprimer extension pg_trgm car d'autres objets en dépendent
2022-01-13 17:03:24.326 CET [364129] jenkins@test_authentic2 DÉTAIL:  index custom_user_name_gist_idx dépend de classe d'opérateur gist_trgm_ops pour la méthode d'accès gist
2022-01-13 17:03:24.326 CET [364129] jenkins@test_authentic2 ASTUCE :  Utilisez DROP ... CASCADE pour supprimer aussi les objets dépendants.
2022-01-13 17:03:24.326 CET [364129] jenkins@test_authentic2 INSTRUCTION :  DROP EXTENSION IF EXISTS pg_trgm
Dropping cluster 13/regress ...

Guillaume Baffoin a écrit :

je regarde les logs dans jenkins, est ce que ces erreurs sont "normales" (elles sont attendues et testés) ?

sinon on dirait qu'il n'arrive pas a purger la base à la fin.

[...]

Hmm, les trucs genre l’extension qu’on n’arrive pas à supprimer, je ne pense pas que ce soit des erreurs "normales"…
Mais ce qui m’intéresserait ici est d’avoir les logs SQL pour le test en question.
En local, j’ai tapé des DEBUG et des DEBUG_DB partout, inspecté tous les fichiers de log possibles, je ne trouve rien. Je suspecte que les logs disparaissent avec la base de test test_authentic2 créée lorsque les tests a2 s’exécutent en local, mais je ne suis plus dans un état de fraîcheur suffisant pour creuser plus loin :)
Je reprends demain.

Et directement sur jenkins.eo.org, les fichiers /var/log/postgresql/postgresql*.log contiennent les logs d’erreurs SQL de toutes les briques sauf … authentic :)
Bref, en local je vais creuser pour exploiter les wal directement, parce qu’à part ça je suis à court d’idées.

J’ai poussé une branche pour avoir plus d’infos côté Jenkins, et maintenant ça plante sur la ligne d’au dessus !

        assert len(users) == 1
        assert User.objects.count() == 1
>       assert all(isinstance(exception, MultipleObjectsReturned) for exception in exceptions)
E       assert False
E        +  where False = all(<generator object test_safe_get_or_create.<locals>.<genexpr> at 0x7fcc2ea06580>)

Des choses restent encore à éclaircir, affaire à suivre.

Une autre possibilité c'est aussi de diminuer le nombre de threads, je vais ouvrir un ticket dans ce sens.

Paul Marillonnet a écrit :

Et directement sur jenkins.eo.org, les fichiers /var/log/postgresql/postgresql*.log contiennent les logs d’erreurs SQL de toutes les briques sauf … authentic :)
Bref, en local je vais creuser pour exploiter les wal directement, parce qu’à part ça je suis à court d’idées.

C'est pas une bonne idée ça.
En local tu peux mettre un log_min_duration_statement à 0, voire le spécifier sur une seule base, voire truander ton django pour le faire sur ton test uniquement. Mais le WAL ne t'aidera pas.

Pour revenir sur le fond du problème, je doute très fortement qu'un changement dans PostgreSQL puisse être à l'origine d'un soucis ici. Il n'y a pas vraiment de "configuration des accès concurrents" en jeu, encore moins une configuration qui serait changée ici.
S'agissant par contre d'un code multi-thread, en python, une fluctuation dans l'ordre de lâcher des GIL et d'ordonnancement des fils d'exécution peut changer dramatiquement le profil d'exécution, donc l'ordre des requêtes SQL, et ipso facto provoquer ce changement sur cette fonction.
D'où l'intérêt d'avoir un log des requêtes SQL exécutées, et pas autre chose. Tout autre élément nous éloignera de la réalité de la communication entre l'application et PostgreSQL.

Pierre Ducroquet a écrit :

Paul Marillonnet a écrit :

Et directement sur jenkins.eo.org, les fichiers /var/log/postgresql/postgresql*.log contiennent les logs d’erreurs SQL de toutes les briques sauf … authentic :)
Bref, en local je vais creuser pour exploiter les wal directement, parce qu’à part ça je suis à court d’idées.

C'est pas une bonne idée ça.
En local tu peux mettre un log_min_duration_statement à 0, voire le spécifier sur une seule base, voire truander ton django pour le faire sur ton test uniquement. Mais le WAL ne t'aidera pas.

D’ac, j’avais suggéré cette idée un peu au comble du désespoir, je vais tenter ce que tu proposes avec le log_min_duration_statement, merci pour le tuyau. Bon, cela dit, a priori on est parti sur une solution plus radicale, #60658.

Automatic expiration