Pendant un blocage de la base de données en préproduction, les jobs planifiés d’un service se sont arrêtés environ trente minutes sans écrire une seule ligne de log.

Cet article fait suite à Quand l’advisory lock ne suffit plus : passer à un lease[1].

Il couvre les deux premiers volets de deux mois d’exploitation du lease : le silence de gocron sur les échecs de verrou, puis le niveau de log à donner à ces échecs.

Une plateforme SaaS, plusieurs services, chacun déployé en plusieurs replicas. Chaque service planifie ses jobs avec gocron v2.22.0, et le lease en table joue le rôle de Locker distribué.

Un échec de Locker.Lock ne passe que par un écouteur

gocron appelle Locker.Lock avant chaque exécution. Si l’appel renvoie une erreur, l’executor appelle l’écouteur AfterLockError, reprogramme le job, incrémente le compteur de sauts et abandonne le tick[2][3].

lock, err := e.locker.Lock(j.ctx, j.name)
if err != nil {
    _ = callJobFuncWithParams(j.afterLockError, j.id, j.name, err)
    e.sendOutForRescheduling(&jIn)
    e.incrementJobCounter(j, Skip)
    e.sendOutForNextRunUpdate(&jIn)
    return
}
defer func() { _ = lock.Unlock(j.ctx) }()

Extrait de executor.go, gocron v2.22.0, branche du locker de scheduler.

gocron ne journalise rien d’elle-même. Sans écouteur enregistré, l’erreur disparaît.

La trace dans nos logs affichant « launching job » est émise donc dans la tâche, soit après la revendication du verrou.

Son absence indiquait que l’échec se produisait sur le chemin du verrou, sans que rien le dise.

La même branche ignore l’erreur de Unlock, par le _ = du defer.

Une libération en échec n’est donc pas journalisée non plus.

Le scheduler du dépôt d’exemple[4], mise à jour à l’occasion de cet article, journalise les deux cas dans internal/scheduler/scheduler.go :

  • reportClaimFailure pour la revendication,
  • release pour la libération.
if err := held.Unlock(releaseCtx); err != nil {
    s.logger.ErrorContext(releaseCtx, "failed to release the job",
        slog.String("job", s.key), slog.String("error", err.Error()))
}

La libération s’exécute sur un contexte propre, borné par releaseTimeout, de sorte qu’un arrêt en cours de job ne l’annule pas.

Le correctif : un log ERROR, sauf pour deux erreurs spécifiques

En production, le correctif enregistre un écouteur AfterLockError qui journalise chaque échec au niveau ERROR.

Deux erreurs sont exclues du log, parce qu’elles ne signalent pas une panne :

  • Le verrou déjà détenu par un autre replica est l’issue normale de chaque tick sur chaque replica qui n’est pas leader.
  • context.Canceled correspond à une revendication qui croise un arrêt gracieux. Sans cette exclusion, chaque déploiement produirait une ERROR que l’on lirait comme une panne de base.

context.DeadlineExceeded n’est pas exclue vu qu’une revendication qui dépasse son délai indique un locker trop lent, et cette information doit apparaître.

Le scheduler du dépôt d’exemple n’utilise pas gocron : sa boucle appelle le Locker elle-même, mais il applique la même règle.
tick traite le verrou déjà détenu comme un saut normal, journalisé en INFO, et confie toute autre erreur à reportClaimFailure.

held, err := s.locker.Lock(ctx, s.key)
if errors.Is(err, lock.ErrAlreadyLocked) {
    s.claimFailures = 0
    s.logger.InfoContext(ctx, "job skipped, another replica holds it", slog.String("job", s.key))

    return
}
if err != nil {
    s.reportClaimFailure(ctx, err)

    return
}
s.claimFailures = 0
defer s.release(ctx, held)

Extrait de tick, internal/scheduler/scheduler.go.

reportClaimFailure écarte d’abord la revendication annulée, puis journalise le reste. Une erreur context.DeadlineExceeded atteint le log comme n’importe quelle autre.

func (s *Scheduler) reportClaimFailure(ctx context.Context, err error) {
    if errors.Is(err, context.Canceled) {
        s.claimFailures = 0

        return
    }
    if ctx.Err() != nil {
        return
    }

    // ... décompte de la série et choix du niveau, décrits plus bas
}

Tester ce qui est journalisé

Les tests du dépôt appellent tick directement, sans attendre de minuteur.
Le Locker de test répond à chaque revendication par l’issue suivante d’une liste, où nil vaut une revendication réussie.

type scriptedLocker struct {
    outcomes []error
    claimed  int
}

func (l *scriptedLocker) Lock(context.Context, string) (lock.Lock, error) {
    outcome := l.outcomes[l.claimed]
    l.claimed++
    if outcome != nil {
        return nil, outcome
    }

    return releasedImmediately{}, nil
}

Le helper tickAll exécute un tick par issue et écrit les logs dans un tampon. claimFailureLevels en extrait le niveau de chaque ligne « failed to claim the job ». L’absence d’un log se lit alors dans la longueur de la liste : quatre ticks, trois lignes.

func TestACanceledClaimIsNotLoggedAndRestartsTheFailureSeries(t *testing.T) {
    logs := &bytes.Buffer{}
    locker := &scriptedLocker{outcomes: []error{errDatabaseDown, errDatabaseDown, context.Canceled, errDatabaseDown}}

    tickAll(t, locker, logs)

    assert.Equal(t, []string{"WARN", "WARN", "WARN"}, claimFailureLevels(logs))
}

Le tick annulé ne produit aucune ligne. Le niveau WARN des trois lignes restantes vient de la dégradation décrite dans la section suivante.

Doser le niveau de log une fois le signal rétabli

Avec le log en place, le volume a été mesuré sur un service, sur l’ensemble de la production, avant la dégradation de niveau. Il est d’environ dix ERROR par jour, soit 0,012 % des revendications. Aucun job n’a basculé en échec, au sens du statut métier du service, à cause de ces échecs de verrou. La fenêtre de mesure n’est pas indiquée et la source est interne, donc sans numéro.

Ces échecs sont transitoires pour une partie des jobs. Un job à intervalle qui se relance au plus tard une minute après retente sa revendication au tick suivant. Une alerte sur le premier échec arriverait avant que quiconque puisse agir.

Pour ces jobs, les deux premiers échecs consécutifs sont journalisés en WARN. Le troisième passe en ERROR.

Les autres jobs gardent l’ERROR dès le premier échec : crons, jobs quotidiens, hebdomadaires ou mensuels, jobs de démarrage ou exécutés une seule fois, et pollers plus lents que la minute. Ils perdent leur occurrence lorsque la revendication échoue.

La série repart à zéro dans trois cas :

  • un verrou obtenu, constaté en production dans l’écouteur BeforeJobRuns, que gocron appelle juste après l’acquisition du verrou, avant le lancement de la tâche (executor.go, ligne 476) ;
  • un verrou déjà détenu par un autre replica ;
  • une erreur context.Canceled.

Le dépôt d’exemple contient une version simplifiée de cette règle. Son scheduler ne gère qu’un seul job, sans distinction de type : la dégradation s’applique à tous les échecs. La suite de reportClaimFailure journalise en WARN tant que le rang de l’échec consécutif est inférieur à claimErrorEscalateAfter = 3.

s.claimFailures++
level := slog.LevelError
if s.degradeClaimFailures && s.claimFailures < claimErrorEscalateAfter {
    level = slog.LevelWarn
}

s.logger.Log(ctx, level, "failed to claim the job",
    slog.String("job", s.key), slog.Int("streak", s.claimFailures), slog.String("error", err.Error()))

Les trois remises à zéro sont visibles dans les extraits de tick et de reportClaimFailure plus haut. L’option WithoutClaimFailureDegradation() journalise chaque échec en ERROR.

Suite de la série

L’article suivant, Le lease en production : libérer un bail sans perdre le fence, traite du passage du DELETE à l’expiration en place, de la purge des clés mortes et de l’identité par mandat. Il contient aussi un erratum sur le fence présenté dans l’article précédent.

Crédits & Ressources

  1. Quand l’advisory lock ne suffit plus : passer à un lease : l’article précédent de la série.
  2. gocron v2 : documentation du package : Locker, WithDistributedLocker et AfterLockError.
  3. gocron v2.22.0 : executor.go : branche du locker, lignes 464 à 474, et BeforeJobRuns, ligne 476.
  4. Dépôt d’exemple : le lease en table et son scheduler.