Projet

Général

Profil

Development #67613

SMS envoyés en double (via OVH ?)

Ajouté par Thomas Noël il y a presque 2 ans. Mis à jour il y a presque 2 ans.

Statut:
Fermé
Priorité:
Normal
Assigné à:
Version cible:
-
Début:
21 juillet 2022
Echéance:
% réalisé:

0%

Temps estimé:
Patch proposed:
Oui
Planning:
Non

Description

Déjà vu deux fois chez deux clients : des SMS envoyés une seule fois dans le workflow, mais reçu deux fois par l'usager.

Quand on regarde au niveau de passerelle, on voit que cela correspond à des "job" dont les moments de création et d'exécution sont séparés de quelques instants... Le premier SMS reçu est au moment de la création du job, le second au moment de l'exécution.

Difficile d'en dire plus, on manque un peu de logs sur les jobs. Mais il faudrait creuser, le nombre de SMS en double se compte en milliers.


Fichiers

Révisions associées

Révision 2d6e8599 (diff)
Ajouté par Valentin Deniaud il y a presque 2 ans

jobs: add missing checks in runjob command (#67613)

Révision 8ae6e9e4 (diff)
Ajouté par Valentin Deniaud il y a presque 2 ans

jobs: add missing checks in runjob command (#67613)

Historique

#4

Mis à jour par Valentin Deniaud il y a presque 2 ans

  • Assigné à mis à Valentin Deniaud

Vu avec Thomas, on est probablement dans le cas où le cron va jouer dans BaseResource.jobs :

 584     def jobs(self):
 ...
 605             with transaction.atomic():
 606                 job = (
 607                     self.jobs_set()
 608                     .exclude(pk__in=skipped_jobs)
 609                     .filter(
 610                         Q(after_timestamp__isnull=True) | Q(after_timestamp__lt=timezone.now()),
 611                         status='registered',
 612                     )
 613                     .select_for_update(**skip_locked)
 614                     .order_by('pk')[:1]
 615                     .first()
 616                 )
 617                 if not job:
 618                     break
 619                 job.status = 'running'
 620                 job.save()
 621                 # release lock
 622             result = job.run()

En même temps, exécution de la commande runjob par le spooler :

 29     def handle(self, *args, **options):
 ...
 33         with transaction.atomic():
 34             try:
 35                 job = Job.objects.select_for_update(**skip_locked).get(pk=options['job_id'])
 36             except Job.DoesNotExist:
 37                 raise CommandError('missing job')
 38             job.status = 'running'
 39             job.save()
 40             # release lock
 41         job.run()

Le code se protège des race conditions de la manière suivante :
  • Dans BaseResource.jobs, récupération du job
  • Il est locké par le select_for_update
  • Si il y a runjob en même temps, le skip_locked fait que le job en cours de traitement n'apparaît pas
Mais, gros trou dans la raquette dans le scénario où :
  • Dans BaseResource.jobs, récupération du job
  • Il est locké par le select_for_update
  • On le place en statut « running »
  • On enlève le lock
  • On l'exécute
Il peut se produire la race condition :
  • Dans BaseResource.jobs, récupération du job
  • Il est locké par le select_for_update
  • On le place en statut « running »
  • On enlève le lock
  • Un runjob parallèle récupère le job (car plus de lock)
  • Exécution par runjob et par BaseResource.jobs

En fait c'est jusque le .filter(status='registered') manque côté runjob (en profiter aussi pour ajouter celui sur le timestamp).

#5

Mis à jour par Thomas Noël il y a presque 2 ans

Valentin Deniaud a écrit :

En fait c'est jusque le .filter(status='registered') manque côté runjob (en profiter aussi pour ajouter celui sur le timestamp).

Même analyse, mais plutôt que des filter, faire :

if job.status != 'registered':
   raise CommandError('cannot run job, status is %s' % job.status)
if job.after_timestamp and job.after_timestamp > maintenant:
   raise CommandError('cannot run job, should be run after ...
...

pour avoir des messages de refus plus clairs ?

#6

Mis à jour par Valentin Deniaud il y a presque 2 ans

#7

Mis à jour par Thomas Noël il y a presque 2 ans

  • Statut changé de Solution proposée à Solution validée
#8

Mis à jour par Valentin Deniaud il y a presque 2 ans

  • Statut changé de Solution validée à Résolu (à déployer)
commit 2d6e859971b76a3b1ffed8addb513e102a9d83a4
Author: Valentin Deniaud <vdeniaud@entrouvert.com>
Date:   Mon Jul 25 13:42:48 2022 +0200

    jobs: add missing checks in runjob command (#67613)
#11

Mis à jour par Thomas Noël il y a presque 2 ans

  • Statut changé de Résolu (à déployer) à Solution déployée

Déployé aussi en hotfix. Activité à surveiller ce mardi.

#12

Mis à jour par Transition automatique il y a plus d'un an

Automatic expiration

Formats disponibles : Atom PDF