Skip to main content

mas_tasks/
new_queue.rs

1// Copyright 2025, 2026 Element Creations Ltd.
2// Copyright 2024, 2025 New Vector Ltd.
3//
4// SPDX-License-Identifier: AGPL-3.0-only OR LicenseRef-Element-Commercial
5// Please see LICENSE files in the repository root for full details.
6
7use std::{collections::HashMap, sync::Arc};
8
9use async_trait::async_trait;
10use chrono::{DateTime, Duration, Utc};
11use cron::Schedule;
12use mas_context::LogContext;
13use mas_data_model::Clock;
14use mas_storage::{
15    RepositoryAccess, RepositoryError,
16    queue::{InsertableJob, Job, JobMetadata, Worker},
17};
18use mas_storage_pg::{DatabaseError, PgRepository};
19use opentelemetry::{
20    KeyValue,
21    metrics::{Counter, Histogram, UpDownCounter},
22};
23use rand::{Rng, RngExt, distr::Uniform};
24use serde::de::DeserializeOwned;
25use sqlx::{
26    Acquire, Either,
27    postgres::{PgAdvisoryLock, PgListener},
28};
29use thiserror::Error;
30use tokio::{task::JoinSet, time::Instant};
31use tokio_util::sync::CancellationToken;
32use tracing::{Instrument as _, Span};
33use tracing_opentelemetry::OpenTelemetrySpanExt as _;
34use ulid::Ulid;
35
36use crate::{METER, State};
37
38type JobPayload = serde_json::Value;
39
40#[derive(Clone)]
41pub struct JobContext {
42    pub id: Ulid,
43    pub metadata: JobMetadata,
44    pub queue_name: String,
45    pub attempt: usize,
46    pub start: Instant,
47    pub cancellation_token: CancellationToken,
48}
49
50impl JobContext {
51    pub fn span(&self) -> Span {
52        let span = tracing::info_span!(
53            parent: Span::none(),
54            "job.run",
55            job.id = %self.id,
56            job.queue.name = self.queue_name,
57            job.attempt = self.attempt,
58        );
59
60        span.add_link(self.metadata.span_context());
61
62        span
63    }
64}
65
66#[derive(Debug, Clone, Copy, PartialEq, Eq, Default)]
67pub enum JobErrorDecision {
68    Retry,
69
70    #[default]
71    Fail,
72}
73
74impl std::fmt::Display for JobErrorDecision {
75    fn fmt(&self, f: &mut std::fmt::Formatter<'_>) -> std::fmt::Result {
76        match self {
77            Self::Retry => f.write_str("retry"),
78            Self::Fail => f.write_str("fail"),
79        }
80    }
81}
82
83#[derive(Debug, Error)]
84#[error("Job failed to run, will {decision}")]
85pub struct JobError {
86    decision: JobErrorDecision,
87    #[source]
88    error: anyhow::Error,
89}
90
91impl JobError {
92    pub fn retry<T: Into<anyhow::Error>>(error: T) -> Self {
93        Self {
94            decision: JobErrorDecision::Retry,
95            error: error.into(),
96        }
97    }
98
99    pub fn fail<T: Into<anyhow::Error>>(error: T) -> Self {
100        Self {
101            decision: JobErrorDecision::Fail,
102            error: error.into(),
103        }
104    }
105}
106
107pub trait FromJob {
108    fn from_job(payload: JobPayload) -> Result<Self, anyhow::Error>
109    where
110        Self: Sized;
111}
112
113impl<T> FromJob for T
114where
115    T: DeserializeOwned,
116{
117    fn from_job(payload: JobPayload) -> Result<Self, anyhow::Error> {
118        serde_json::from_value(payload).map_err(Into::into)
119    }
120}
121
122#[async_trait]
123pub trait RunnableJob: Send + 'static {
124    async fn run(&self, state: &State, context: JobContext) -> Result<(), JobError>;
125
126    /// Allows the job to set a timeout for its execution. Jobs should then look
127    /// at the cancellation token passed in the [`JobContext`] to handle
128    /// graceful shutdowns.
129    fn timeout(&self) -> Option<std::time::Duration> {
130        None
131    }
132}
133
134fn box_runnable_job<T: RunnableJob + 'static>(job: T) -> Box<dyn RunnableJob> {
135    Box::new(job)
136}
137
138#[derive(Debug, Error)]
139pub enum QueueRunnerError {
140    #[error("Failed to setup listener")]
141    SetupListener(#[source] sqlx::Error),
142
143    #[error("Failed to start transaction")]
144    StartTransaction(#[source] sqlx::Error),
145
146    #[error("Failed to commit transaction")]
147    CommitTransaction(#[source] sqlx::Error),
148
149    #[error("Failed to acquire leader lock")]
150    LeaderLock(#[source] sqlx::Error),
151
152    #[error(transparent)]
153    Repository(#[from] RepositoryError),
154
155    #[error(transparent)]
156    Database(#[from] DatabaseError),
157
158    #[error("Invalid schedule expression")]
159    InvalidSchedule(#[from] cron::error::Error),
160
161    #[error("Worker is not the leader")]
162    NotLeader,
163}
164
165// When the worker waits for a notification, we still want to wake it up every
166// second. Because we don't want all the workers to wake up at the same time, we
167// add a random jitter to the sleep duration, so they effectively sleep between
168// 0.9 and 1.1 seconds.
169const MIN_SLEEP_DURATION: std::time::Duration = std::time::Duration::from_millis(900);
170const MAX_SLEEP_DURATION: std::time::Duration = std::time::Duration::from_millis(1100);
171
172// How many jobs can we run concurrently
173const MAX_CONCURRENT_JOBS: usize = 10;
174
175// How many jobs can we fetch at once
176const MAX_JOBS_TO_FETCH: usize = 5;
177
178// How many attempts a job should be retried
179const MAX_ATTEMPTS: usize = 10;
180
181/// Returns the delay to wait before retrying a job
182///
183/// Uses an exponential backoff: 5s, 10s, 20s, 40s, 1m20s, 2m40s, 5m20s, 10m50s,
184/// 21m40s, 43m20s
185fn retry_delay(attempt: usize) -> Duration {
186    let attempt = u32::try_from(attempt).unwrap_or(u32::MAX);
187    Duration::milliseconds(2_i64.saturating_pow(attempt) * 5_000)
188}
189
190type JobResult = (std::time::Duration, Result<(), JobError>);
191type JobFactory = Arc<dyn Fn(JobPayload) -> Box<dyn RunnableJob> + Send + Sync>;
192
193/// This is a fake job we use to consume jobs from deprecated queues
194struct DeprecatedJob;
195
196#[async_trait]
197impl RunnableJob for DeprecatedJob {
198    async fn run(&self, _state: &State, context: JobContext) -> Result<(), JobError> {
199        tracing::warn!(
200            job.id = %context.id,
201            job.queue.name = context.queue_name,
202            "Consumed a job from a deprecated queue, which can happen after version upgrades. This did nothing other than removing the job from the queue."
203        );
204
205        Ok(())
206    }
207}
208
209struct ScheduleDefinition {
210    schedule_name: &'static str,
211    expression: Schedule,
212    queue_name: &'static str,
213    payload: serde_json::Value,
214}
215
216pub struct QueueWorker {
217    listener: PgListener,
218    registration: Worker,
219    am_i_leader: bool,
220    last_heartbeat: DateTime<Utc>,
221    cancellation_token: CancellationToken,
222    #[expect(dead_code, reason = "This is used on Drop")]
223    cancellation_guard: tokio_util::sync::DropGuard,
224    state: State,
225    schedules: Vec<ScheduleDefinition>,
226    tracker: JobTracker,
227    wakeup_reason: Counter<u64>,
228    tick_time: Histogram<u64>,
229}
230
231impl QueueWorker {
232    #[tracing::instrument(
233        name = "worker.init",
234        skip_all,
235        fields(worker.id)
236    )]
237    pub(crate) async fn new(
238        state: State,
239        cancellation_token: CancellationToken,
240    ) -> Result<Self, QueueRunnerError> {
241        let mut rng = state.rng();
242        let clock = state.clock();
243
244        let mut listener = PgListener::connect_with(&state.pool())
245            .await
246            .map_err(QueueRunnerError::SetupListener)?;
247
248        // We get notifications of leader stepping down on this channel
249        listener
250            .listen("queue_leader_stepdown")
251            .await
252            .map_err(QueueRunnerError::SetupListener)?;
253
254        // We get notifications when a job is available on this channel
255        listener
256            .listen("queue_available")
257            .await
258            .map_err(QueueRunnerError::SetupListener)?;
259
260        let txn = listener
261            .begin()
262            .await
263            .map_err(QueueRunnerError::StartTransaction)?;
264        let mut repo = PgRepository::from_conn(txn);
265
266        let registration = repo.queue_worker().register(&mut rng, clock).await?;
267        tracing::Span::current().record("worker.id", tracing::field::display(registration.id));
268        repo.into_inner()
269            .commit()
270            .await
271            .map_err(QueueRunnerError::CommitTransaction)?;
272
273        tracing::info!(worker.id = %registration.id, "Registered worker");
274        let now = clock.now();
275
276        let wakeup_reason = METER
277            .u64_counter("job.worker.wakeups")
278            .with_description("Counts how many time the worker has been woken up, for which reason")
279            .build();
280
281        // Pre-create the reasons on the counter
282        wakeup_reason.add(0, &[KeyValue::new("reason", "sleep")]);
283        wakeup_reason.add(0, &[KeyValue::new("reason", "task")]);
284        wakeup_reason.add(0, &[KeyValue::new("reason", "notification")]);
285
286        let tick_time = METER
287            .u64_histogram("job.worker.tick_duration")
288            .with_description(
289                "How much time the worker took to tick, including performing leader duties",
290            )
291            .build();
292
293        // We put a cancellation drop guard in the structure, so that when it gets
294        // dropped, we're sure to cancel the token
295        let cancellation_guard = cancellation_token.clone().drop_guard();
296
297        Ok(Self {
298            listener,
299            registration,
300            am_i_leader: false,
301            last_heartbeat: now,
302            cancellation_token,
303            cancellation_guard,
304            state,
305            schedules: Vec::new(),
306            tracker: JobTracker::new(),
307            wakeup_reason,
308            tick_time,
309        })
310    }
311
312    pub(crate) fn register_handler<T: RunnableJob + InsertableJob + FromJob>(
313        &mut self,
314    ) -> &mut Self {
315        // There is a potential panic here, which is fine as it's going to be caught
316        // within the job task
317        let factory = |payload: JobPayload| {
318            box_runnable_job(T::from_job(payload).expect("Failed to deserialize job"))
319        };
320
321        self.tracker
322            .factories
323            .insert(T::QUEUE_NAME, Arc::new(factory));
324        self
325    }
326
327    /// Register a queue name as deprecated, which will consume leftover jobs
328    pub(crate) fn register_deprecated_queue(&mut self, queue_name: &'static str) -> &mut Self {
329        let factory = |_payload: JobPayload| box_runnable_job(DeprecatedJob);
330        self.tracker.factories.insert(queue_name, Arc::new(factory));
331        self
332    }
333
334    pub(crate) fn add_schedule<T: InsertableJob>(
335        &mut self,
336        schedule_name: &'static str,
337        expression: Schedule,
338        job: T,
339    ) -> &mut Self {
340        let payload = serde_json::to_value(job).expect("failed to serialize job payload");
341
342        self.schedules.push(ScheduleDefinition {
343            schedule_name,
344            expression,
345            queue_name: T::QUEUE_NAME,
346            payload,
347        });
348
349        self
350    }
351
352    pub(crate) async fn run(mut self) {
353        if let Err(e) = self.run_inner().await {
354            tracing::error!(
355                error = &e as &dyn std::error::Error,
356                "Failed to run new queue"
357            );
358        }
359    }
360
361    async fn run_inner(&mut self) -> Result<(), QueueRunnerError> {
362        self.setup_schedules().await?;
363
364        while !self.cancellation_token.is_cancelled() {
365            LogContext::new("worker-run-loop")
366                .run(|| self.run_loop())
367                .await?;
368        }
369
370        self.shutdown().await?;
371
372        Ok(())
373    }
374
375    #[tracing::instrument(name = "worker.setup_schedules", skip_all)]
376    pub(crate) async fn setup_schedules(&mut self) -> Result<(), QueueRunnerError> {
377        let schedules: Vec<_> = self.schedules.iter().map(|s| s.schedule_name).collect();
378
379        // Start a transaction on the existing PgListener connection
380        let txn = self
381            .listener
382            .begin()
383            .await
384            .map_err(QueueRunnerError::StartTransaction)?;
385
386        let mut repo = PgRepository::from_conn(txn);
387
388        // Setup the entries in the queue_schedules table
389        repo.queue_schedule().setup(&schedules).await?;
390
391        repo.into_inner()
392            .commit()
393            .await
394            .map_err(QueueRunnerError::CommitTransaction)?;
395
396        Ok(())
397    }
398
399    #[tracing::instrument(name = "worker.run_loop", skip_all)]
400    async fn run_loop(&mut self) -> Result<(), QueueRunnerError> {
401        self.wait_until_wakeup().await?;
402
403        if self.cancellation_token.is_cancelled() {
404            return Ok(());
405        }
406
407        let start = Instant::now();
408        self.tick().await?;
409
410        if self.am_i_leader {
411            self.perform_leader_duties().await?;
412        }
413
414        let elapsed = start.elapsed().as_millis().try_into().unwrap_or(u64::MAX);
415        self.tick_time.record(elapsed, &[]);
416
417        Ok(())
418    }
419
420    #[tracing::instrument(name = "worker.shutdown", skip_all)]
421    async fn shutdown(&mut self) -> Result<(), QueueRunnerError> {
422        tracing::info!("Shutting down worker");
423
424        let clock = self.state.clock();
425        let mut rng = self.state.rng();
426
427        // Start a transaction on the existing PgListener connection
428        let txn = self
429            .listener
430            .begin()
431            .await
432            .map_err(QueueRunnerError::StartTransaction)?;
433
434        let mut repo = PgRepository::from_conn(txn);
435
436        // Log about any job still running
437        match self.tracker.running_jobs() {
438            0 => {}
439            1 => tracing::warn!("There is one job still running, waiting for it to finish"),
440            n => tracing::warn!("There are {n} jobs still running, waiting for them to finish"),
441        }
442
443        // TODO: we may want to introduce a timeout here, and abort the tasks if they
444        // take too long. It's fine for now, as we don't have long-running
445        // tasks, most of them are idempotent, and the only effect might be that
446        // the worker would 'dirtily' shutdown, meaning that its tasks would be
447        // considered, later retried by another worker
448
449        // Wait for all the jobs to finish
450        self.tracker
451            .process_jobs(&mut rng, clock, &mut repo, true)
452            .await?;
453
454        // Tell the other workers we're shutting down
455        // This also releases the leader election lease
456        repo.queue_worker()
457            .shutdown(clock, &self.registration)
458            .await?;
459
460        repo.into_inner()
461            .commit()
462            .await
463            .map_err(QueueRunnerError::CommitTransaction)?;
464
465        Ok(())
466    }
467
468    #[tracing::instrument(name = "worker.wait_until_wakeup", skip_all)]
469    async fn wait_until_wakeup(&mut self) -> Result<(), QueueRunnerError> {
470        let mut rng = self.state.rng();
471
472        // This is to make sure we wake up every second to do the maintenance tasks
473        // We add a little bit of random jitter to the duration, so that we don't get
474        // fully synced workers waking up at the same time after each notification
475        let sleep_duration =
476            rng.sample(Uniform::new(MIN_SLEEP_DURATION, MAX_SLEEP_DURATION).expect("valid range"));
477        let wakeup_sleep = tokio::time::sleep(sleep_duration);
478
479        tokio::select! {
480            () = self.cancellation_token.cancelled() => {
481                tracing::debug!("Woke up from cancellation");
482            },
483
484            () = wakeup_sleep => {
485                tracing::debug!("Woke up from sleep");
486                self.wakeup_reason.add(1, &[KeyValue::new("reason", "sleep")]);
487            },
488
489            () = self.tracker.collect_next_job(), if self.tracker.has_jobs() => {
490                tracing::debug!("Joined job task");
491                self.wakeup_reason.add(1, &[KeyValue::new("reason", "task")]);
492            },
493
494            notification = self.listener.recv() => {
495                self.wakeup_reason.add(1, &[KeyValue::new("reason", "notification")]);
496                match notification {
497                    Ok(notification) => {
498                        tracing::debug!(
499                            notification.channel = notification.channel(),
500                            notification.payload = notification.payload(),
501                            "Woke up from notification"
502                        );
503                    },
504                    Err(e) => {
505                        tracing::error!(error = &e as &dyn std::error::Error, "Failed to receive notification");
506                    },
507                }
508            },
509        }
510
511        Ok(())
512    }
513
514    #[tracing::instrument(
515        name = "worker.tick",
516        skip_all,
517        fields(worker.id = %self.registration.id),
518    )]
519    async fn tick(&mut self) -> Result<(), QueueRunnerError> {
520        tracing::debug!("Tick");
521        let clock = self.state.clock();
522        let mut rng = self.state.rng();
523        let now = clock.now();
524
525        // Start a transaction on the existing PgListener connection
526        let txn = self
527            .listener
528            .begin()
529            .await
530            .map_err(QueueRunnerError::StartTransaction)?;
531        let mut repo = PgRepository::from_conn(txn);
532
533        // We send a heartbeat every minute, to avoid writing to the database too often
534        // on a logged table
535        if now - self.last_heartbeat >= chrono::Duration::minutes(1) {
536            tracing::info!("Sending heartbeat");
537            repo.queue_worker()
538                .heartbeat(clock, &self.registration)
539                .await?;
540            self.last_heartbeat = now;
541        }
542
543        // Remove any dead worker leader leases
544        repo.queue_worker()
545            .remove_leader_lease_if_expired(clock)
546            .await?;
547
548        // Try to become (or stay) the leader
549        let leader = repo
550            .queue_worker()
551            .try_get_leader_lease(clock, &self.registration)
552            .await?;
553
554        // Process any job task which finished
555        self.tracker
556            .process_jobs(&mut rng, clock, &mut repo, false)
557            .await?;
558
559        // Compute how many jobs we should fetch at most
560        let max_jobs_to_fetch = MAX_CONCURRENT_JOBS
561            .saturating_sub(self.tracker.running_jobs())
562            .min(MAX_JOBS_TO_FETCH);
563
564        if max_jobs_to_fetch == 0 {
565            tracing::warn!("Internal job queue is full, not fetching any new jobs");
566        } else {
567            // Grab a few jobs in the queue
568            let queues = self.tracker.queues();
569            let jobs = repo
570                .queue_job()
571                .reserve(clock, &self.registration, &queues, max_jobs_to_fetch)
572                .await?;
573
574            for Job {
575                id,
576                queue_name,
577                payload,
578                metadata,
579                attempt,
580            } in jobs
581            {
582                let cancellation_token = self.cancellation_token.child_token();
583                let start = Instant::now();
584                let context = JobContext {
585                    id,
586                    metadata,
587                    queue_name,
588                    attempt,
589                    start,
590                    cancellation_token,
591                };
592
593                self.tracker.spawn_job(self.state.clone(), context, payload);
594            }
595        }
596
597        // After this point, we are locking the leader table, so it's important that we
598        // commit as soon as possible to not block the other workers for too long
599        repo.into_inner()
600            .commit()
601            .await
602            .map_err(QueueRunnerError::CommitTransaction)?;
603
604        // Save the new leader state to log any change
605        if leader != self.am_i_leader {
606            // If we flipped state, log it
607            self.am_i_leader = leader;
608            if self.am_i_leader {
609                tracing::info!("I'm the leader now");
610            } else {
611                tracing::warn!("I am no longer the leader");
612            }
613        }
614
615        Ok(())
616    }
617
618    #[tracing::instrument(name = "worker.perform_leader_duties", skip_all)]
619    async fn perform_leader_duties(&mut self) -> Result<(), QueueRunnerError> {
620        // This should have been checked by the caller, but better safe than sorry
621        if !self.am_i_leader {
622            return Err(QueueRunnerError::NotLeader);
623        }
624
625        let clock = self.state.clock();
626        let mut rng = self.state.rng();
627
628        // Start a transaction on the existing PgListener connection
629        let txn = self
630            .listener
631            .begin()
632            .await
633            .map_err(QueueRunnerError::StartTransaction)?;
634
635        // The thing with the leader election is that it locks the table during the
636        // election, preventing other workers from going through the loop.
637        //
638        // Ideally, we would do the leader duties in the same transaction so that we
639        // make sure only one worker is doing the leader duties, but that
640        // would mean we would lock all the workers for the duration of the
641        // duties, which is not ideal.
642        //
643        // So we do the duties in a separate transaction, in which we take an advisory
644        // lock, so that in the very rare case where two workers think they are the
645        // leader, we still don't have two workers doing the duties at the same time.
646        let lock = PgAdvisoryLock::new("leader-duties");
647
648        let locked = lock
649            .try_acquire(txn)
650            .await
651            .map_err(QueueRunnerError::LeaderLock)?;
652
653        let locked = match locked {
654            Either::Left(locked) => locked,
655            Either::Right(txn) => {
656                tracing::error!("Another worker has the leader lock, aborting");
657                txn.rollback()
658                    .await
659                    .map_err(QueueRunnerError::CommitTransaction)?;
660                return Ok(());
661            }
662        };
663
664        let mut repo = PgRepository::from_conn(locked);
665
666        // Look at the state of schedules in the database
667        let schedules_status = repo.queue_schedule().list().await?;
668
669        let now = clock.now();
670        for schedule in &self.schedules {
671            // Find the schedule status from the database
672            let Some(status) = schedules_status
673                .iter()
674                .find(|s| s.schedule_name == schedule.schedule_name)
675            else {
676                tracing::error!(
677                    "Schedule {} was not found in the database",
678                    schedule.schedule_name
679                );
680                continue;
681            };
682
683            // Figure out if we should schedule a new job
684            if let Some(next_time) = status.last_scheduled_at {
685                if next_time > now {
686                    // We already have a job scheduled in the future, skip
687                    continue;
688                }
689
690                if status.last_scheduled_job_completed == Some(false) {
691                    // The last scheduled job has not completed yet, skip
692                    continue;
693                }
694            }
695
696            let next_tick = schedule.expression.after(&now).next().unwrap();
697
698            tracing::info!(
699                "Scheduling job for {}, next run at {}",
700                schedule.schedule_name,
701                next_tick
702            );
703
704            repo.queue_job()
705                .schedule_later(
706                    &mut rng,
707                    clock,
708                    schedule.queue_name,
709                    schedule.payload.clone(),
710                    serde_json::json!({}),
711                    next_tick,
712                    Some(schedule.schedule_name),
713                )
714                .await?;
715        }
716
717        // We also check if the worker is dead, and if so, we shutdown all the dead
718        // workers that haven't checked in the last two minutes
719        repo.queue_worker()
720            .shutdown_dead_workers(clock, Duration::minutes(2))
721            .await?;
722
723        // TODO: mark tasks those workers had as lost
724
725        // Mark all the scheduled jobs as available
726        let scheduled = repo.queue_job().schedule_available_jobs(clock).await?;
727        match scheduled {
728            0 => {}
729            1 => tracing::info!("One scheduled job marked as available"),
730            n => tracing::info!("{n} scheduled jobs marked as available"),
731        }
732
733        // Release the leader lock
734        let txn = repo
735            .into_inner()
736            .release_now()
737            .await
738            .map_err(QueueRunnerError::LeaderLock)?;
739
740        txn.commit()
741            .await
742            .map_err(QueueRunnerError::CommitTransaction)?;
743
744        Ok(())
745    }
746
747    /// Process all the pending jobs in the queue.
748    /// This should only be called in tests!
749    ///
750    /// # Errors
751    ///
752    /// This function can fail if the database connection fails.
753    pub async fn process_all_jobs_in_tests(&mut self) -> Result<(), QueueRunnerError> {
754        // In case we haven't setup the schedules yet
755        self.setup_schedules().await?;
756
757        // I swear, I'm the leader!
758        self.am_i_leader = true;
759
760        // First, perform the leader duties. This will make sure that we schedule
761        // recurring jobs.
762        self.perform_leader_duties().await?;
763
764        let clock = self.state.clock();
765        let mut rng = self.state.rng();
766
767        // Grab the connection from the PgListener
768        let txn = self
769            .listener
770            .begin()
771            .await
772            .map_err(QueueRunnerError::StartTransaction)?;
773        let mut repo = PgRepository::from_conn(txn);
774
775        // Spawn all the jobs in the database
776        let queues = self.tracker.queues();
777        let jobs = repo
778            .queue_job()
779            // I really hope that we don't spawn more than 10k jobs in tests
780            .reserve(clock, &self.registration, &queues, 10_000)
781            .await?;
782
783        for Job {
784            id,
785            queue_name,
786            payload,
787            metadata,
788            attempt,
789        } in jobs
790        {
791            let cancellation_token = self.cancellation_token.child_token();
792            let start = Instant::now();
793            let context = JobContext {
794                id,
795                metadata,
796                queue_name,
797                attempt,
798                start,
799                cancellation_token,
800            };
801
802            self.tracker.spawn_job(self.state.clone(), context, payload);
803        }
804
805        self.tracker
806            .process_jobs(&mut rng, clock, &mut repo, true)
807            .await?;
808
809        repo.into_inner()
810            .commit()
811            .await
812            .map_err(QueueRunnerError::CommitTransaction)?;
813
814        Ok(())
815    }
816}
817
818/// Tracks running jobs
819///
820/// This is a separate structure to be able to borrow it mutably at the same
821/// time as the connection to the database is borrowed
822struct JobTracker {
823    /// Stores a mapping from the job queue name to the job factory
824    factories: HashMap<&'static str, JobFactory>,
825
826    /// A join set of all the currently running jobs
827    running_jobs: JoinSet<JobResult>,
828
829    /// Stores a mapping from the Tokio task ID to the job context
830    job_contexts: HashMap<tokio::task::Id, JobContext>,
831
832    /// Stores the last `join_next_with_id` result for processing, in case we
833    /// got woken up in `collect_next_job`
834    last_join_result: Option<Result<(tokio::task::Id, JobResult), tokio::task::JoinError>>,
835
836    /// An histogram which records the time it takes to process a job
837    job_processing_time: Histogram<u64>,
838
839    /// A counter which records the number of jobs currently in flight
840    in_flight_jobs: UpDownCounter<i64>,
841}
842
843impl JobTracker {
844    fn new() -> Self {
845        let job_processing_time = METER
846            .u64_histogram("job.process.duration")
847            .with_description("The time it takes to process a job in milliseconds")
848            .with_unit("ms")
849            .build();
850
851        let in_flight_jobs = METER
852            .i64_up_down_counter("job.active_tasks")
853            .with_description("The number of jobs currently in flight")
854            .with_unit("{job}")
855            .build();
856
857        Self {
858            factories: HashMap::new(),
859            running_jobs: JoinSet::new(),
860            job_contexts: HashMap::new(),
861            last_join_result: None,
862            job_processing_time,
863            in_flight_jobs,
864        }
865    }
866
867    /// Returns the queue names that are currently being tracked
868    fn queues(&self) -> Vec<&'static str> {
869        self.factories.keys().copied().collect()
870    }
871
872    /// Spawn a job on the job tracker
873    fn spawn_job(&mut self, state: State, context: JobContext, payload: JobPayload) {
874        let factory = self.factories.get(context.queue_name.as_str()).cloned();
875        let task = {
876            let log_context = LogContext::new(format!("job-{}", context.queue_name));
877            let context = context.clone();
878            let span = context.span();
879            log_context
880                .run(async move || {
881                    // We should never crash, but in case we do, we do that in the task and
882                    // don't crash the worker
883                    let job = factory.expect("unknown job factory")(payload);
884
885                    let timeout = job.timeout();
886                    // If there is a timeout set on the job, spawn a task which will cancel the
887                    // CancellationToken once the timeout is reached
888                    if let Some(timeout) = timeout {
889                        let context = context.clone();
890
891                        // It's fine to spawn this task without tracking it, as it is quite
892                        // lightweight and has no reason to crash.
893                        tokio::spawn(
894                            context
895                                .cancellation_token
896                                .clone()
897                                // This makes sure the task gets cancelled as soon as the job
898                                // finishes
899                                .run_until_cancelled_owned(async move {
900                                    tokio::time::sleep(timeout).await;
901                                    tracing::warn!(
902                                        job.id = %context.id,
903                                        job.queue.name = %context.queue_name,
904                                        "Job reached timeout, asking for cancellation"
905                                    );
906                                    context.cancellation_token.cancel();
907                                }),
908                        );
909                    }
910
911                    tracing::info!(
912                        job.id = %context.id,
913                        job.queue.name = %context.queue_name,
914                        job.attempt = %context.attempt,
915                        job.timeout = timeout.map(tracing::field::debug),
916                        "Running job"
917                    );
918                    let result = job.run(&state, context.clone()).await;
919
920                    // Cancel the cancellation token to stop any timeout task
921                    // that may be running
922                    context.cancellation_token.cancel();
923
924                    let Some(context_stats) =
925                        LogContext::maybe_with(mas_context::LogContext::stats)
926                    else {
927                        // This should never happen, but if it does it's fine: we're recovering fine
928                        // from panics in those tasks
929                        panic!("Missing log context, this should never happen");
930                    };
931
932                    // We log the result here so that it's attached to the right span & log context
933                    match &result {
934                        Ok(()) => {
935                            tracing::info!(
936                                job.id = %context.id,
937                                job.queue.name = %context.queue_name,
938                                job.attempt = %context.attempt,
939                                "Job completed [{context_stats}]"
940                            );
941                        }
942
943                        Err(JobError {
944                            decision: JobErrorDecision::Fail,
945                            error,
946                        }) => {
947                            tracing::error!(
948                                error = &**error as &dyn std::error::Error,
949                                job.id = %context.id,
950                                job.queue.name = %context.queue_name,
951                                job.attempt = %context.attempt,
952                                "Job failed, not retrying [{context_stats}]"
953                            );
954                        }
955
956                        Err(JobError {
957                            decision: JobErrorDecision::Retry,
958                            error,
959                        }) if context.attempt < MAX_ATTEMPTS => {
960                            let delay = retry_delay(context.attempt);
961                            tracing::warn!(
962                                error = &**error as &dyn std::error::Error,
963                                job.id = %context.id,
964                                job.queue.name = %context.queue_name,
965                                job.attempt = %context.attempt,
966                                "Job failed, will retry in {}s [{context_stats}]",
967                                delay.num_seconds()
968                            );
969                        }
970
971                        Err(JobError {
972                            decision: JobErrorDecision::Retry,
973                            error,
974                        }) => {
975                            tracing::error!(
976                                error = &**error as &dyn std::error::Error,
977                                job.id = %context.id,
978                                job.queue.name = %context.queue_name,
979                                job.attempt = %context.attempt,
980                                "Job failed too many times, abandonning [{context_stats}]"
981                            );
982                        }
983                    }
984
985                    (context_stats.elapsed, result)
986                })
987                .instrument(span)
988        };
989
990        self.in_flight_jobs.add(
991            1,
992            &[KeyValue::new("job.queue.name", context.queue_name.clone())],
993        );
994
995        let handle = self.running_jobs.spawn(task);
996        self.job_contexts.insert(handle.id(), context);
997    }
998
999    /// Returns `true` if there are currently running jobs
1000    fn has_jobs(&self) -> bool {
1001        !self.running_jobs.is_empty()
1002    }
1003
1004    /// Returns the number of currently running jobs
1005    ///
1006    /// This also includes the job result which may be stored for processing
1007    fn running_jobs(&self) -> usize {
1008        self.running_jobs.len() + usize::from(self.last_join_result.is_some())
1009    }
1010
1011    async fn collect_next_job(&mut self) {
1012        // Double-check that we don't have a job result stored
1013        if self.last_join_result.is_some() {
1014            tracing::error!(
1015                "Job tracker already had a job result stored, this should never happen!"
1016            );
1017            return;
1018        }
1019
1020        self.last_join_result = self.running_jobs.join_next_with_id().await;
1021    }
1022
1023    /// Process all the jobs which are currently running
1024    ///
1025    /// If `blocking` is `true`, this function will block until all the jobs
1026    /// are finished. Otherwise, it will return as soon as it processed the
1027    /// already finished jobs.
1028    async fn process_jobs<E: std::error::Error + Send + Sync + 'static>(
1029        &mut self,
1030        rng: &mut (dyn Rng + Send),
1031        clock: &dyn Clock,
1032        repo: &mut dyn RepositoryAccess<Error = E>,
1033        blocking: bool,
1034    ) -> Result<(), E> {
1035        if self.last_join_result.is_none() {
1036            if blocking {
1037                self.last_join_result = self.running_jobs.join_next_with_id().await;
1038            } else {
1039                self.last_join_result = self.running_jobs.try_join_next_with_id();
1040            }
1041        }
1042
1043        while let Some(result) = self.last_join_result.take() {
1044            match result {
1045                // The job succeeded. The logging and time measurement is already done in the task
1046                Ok((id, (elapsed, Ok(())))) => {
1047                    let context = self
1048                        .job_contexts
1049                        .remove(&id)
1050                        .expect("Job context not found");
1051
1052                    self.in_flight_jobs.add(
1053                        -1,
1054                        &[KeyValue::new("job.queue.name", context.queue_name.clone())],
1055                    );
1056
1057                    let elapsed_ms = elapsed.as_millis().try_into().unwrap_or(u64::MAX);
1058                    self.job_processing_time.record(
1059                        elapsed_ms,
1060                        &[
1061                            KeyValue::new("job.queue.name", context.queue_name),
1062                            KeyValue::new("job.result", "success"),
1063                        ],
1064                    );
1065
1066                    repo.queue_job()
1067                        .mark_as_completed(clock, context.id)
1068                        .await?;
1069                }
1070
1071                // The job failed. The logging and time measurement is already done in the task
1072                Ok((id, (elapsed, Err(e)))) => {
1073                    let context = self
1074                        .job_contexts
1075                        .remove(&id)
1076                        .expect("Job context not found");
1077
1078                    self.in_flight_jobs.add(
1079                        -1,
1080                        &[KeyValue::new("job.queue.name", context.queue_name.clone())],
1081                    );
1082
1083                    let reason = format!("{:?}", e.error);
1084                    repo.queue_job()
1085                        .mark_as_failed(clock, context.id, &reason)
1086                        .await?;
1087
1088                    let elapsed_ms = elapsed.as_millis().try_into().unwrap_or(u64::MAX);
1089                    match e.decision {
1090                        JobErrorDecision::Fail => {
1091                            self.job_processing_time.record(
1092                                elapsed_ms,
1093                                &[
1094                                    KeyValue::new("job.queue.name", context.queue_name),
1095                                    KeyValue::new("job.result", "failed"),
1096                                    KeyValue::new("job.decision", "fail"),
1097                                ],
1098                            );
1099                        }
1100
1101                        JobErrorDecision::Retry if context.attempt < MAX_ATTEMPTS => {
1102                            self.job_processing_time.record(
1103                                elapsed_ms,
1104                                &[
1105                                    KeyValue::new("job.queue.name", context.queue_name),
1106                                    KeyValue::new("job.result", "failed"),
1107                                    KeyValue::new("job.decision", "retry"),
1108                                ],
1109                            );
1110
1111                            let delay = retry_delay(context.attempt);
1112                            repo.queue_job()
1113                                .retry(&mut *rng, clock, context.id, delay)
1114                                .await?;
1115                        }
1116
1117                        JobErrorDecision::Retry => {
1118                            self.job_processing_time.record(
1119                                elapsed_ms,
1120                                &[
1121                                    KeyValue::new("job.queue.name", context.queue_name),
1122                                    KeyValue::new("job.result", "failed"),
1123                                    KeyValue::new("job.decision", "abandon"),
1124                                ],
1125                            );
1126                        }
1127                    }
1128                }
1129
1130                // The job crashed (or was aborted)
1131                Err(e) => {
1132                    let id = e.id();
1133                    let context = self
1134                        .job_contexts
1135                        .remove(&id)
1136                        .expect("Job context not found");
1137
1138                    self.in_flight_jobs.add(
1139                        -1,
1140                        &[KeyValue::new("job.queue.name", context.queue_name.clone())],
1141                    );
1142
1143                    // This measurement is not accurate as it includes the time processing the jobs,
1144                    // but it's fine, it's only for panicked tasks
1145                    let elapsed = context
1146                        .start
1147                        .elapsed()
1148                        .as_millis()
1149                        .try_into()
1150                        .unwrap_or(u64::MAX);
1151
1152                    let reason = e.to_string();
1153                    repo.queue_job()
1154                        .mark_as_failed(clock, context.id, &reason)
1155                        .await?;
1156
1157                    if context.attempt < MAX_ATTEMPTS {
1158                        let delay = retry_delay(context.attempt);
1159                        tracing::error!(
1160                            error = &e as &dyn std::error::Error,
1161                            job.id = %context.id,
1162                            job.queue.name = %context.queue_name,
1163                            job.attempt = %context.attempt,
1164                            job.elapsed = format!("{elapsed}ms"),
1165                            "Job crashed, will retry in {}s",
1166                            delay.num_seconds()
1167                        );
1168
1169                        self.job_processing_time.record(
1170                            elapsed,
1171                            &[
1172                                KeyValue::new("job.queue.name", context.queue_name),
1173                                KeyValue::new("job.result", "crashed"),
1174                                KeyValue::new("job.decision", "retry"),
1175                            ],
1176                        );
1177
1178                        repo.queue_job()
1179                            .retry(&mut *rng, clock, context.id, delay)
1180                            .await?;
1181                    } else {
1182                        tracing::error!(
1183                            error = &e as &dyn std::error::Error,
1184                            job.id = %context.id,
1185                            job.queue.name = %context.queue_name,
1186                            job.attempt = %context.attempt,
1187                            job.elapsed = format!("{elapsed}ms"),
1188                            "Job crashed too many times, abandonning"
1189                        );
1190
1191                        self.job_processing_time.record(
1192                            elapsed,
1193                            &[
1194                                KeyValue::new("job.queue.name", context.queue_name),
1195                                KeyValue::new("job.result", "crashed"),
1196                                KeyValue::new("job.decision", "abandon"),
1197                            ],
1198                        );
1199                    }
1200                }
1201            }
1202
1203            if blocking {
1204                self.last_join_result = self.running_jobs.join_next_with_id().await;
1205            } else {
1206                self.last_join_result = self.running_jobs.try_join_next_with_id();
1207            }
1208        }
1209
1210        Ok(())
1211    }
1212}