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