1use 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 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
165const 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
172const MAX_CONCURRENT_JOBS: usize = 10;
174
175const MAX_JOBS_TO_FETCH: usize = 5;
177
178const MAX_ATTEMPTS: usize = 10;
180
181fn 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
193struct 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 listener
250 .listen("queue_leader_stepdown")
251 .await
252 .map_err(QueueRunnerError::SetupListener)?;
253
254 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 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 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 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 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 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 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 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 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 self.tracker
451 .process_jobs(&mut rng, clock, &mut repo, true)
452 .await?;
453
454 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 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 let txn = self
527 .listener
528 .begin()
529 .await
530 .map_err(QueueRunnerError::StartTransaction)?;
531 let mut repo = PgRepository::from_conn(txn);
532
533 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 repo.queue_worker()
545 .remove_leader_lease_if_expired(clock)
546 .await?;
547
548 let leader = repo
550 .queue_worker()
551 .try_get_leader_lease(clock, &self.registration)
552 .await?;
553
554 self.tracker
556 .process_jobs(&mut rng, clock, &mut repo, false)
557 .await?;
558
559 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 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 repo.into_inner()
600 .commit()
601 .await
602 .map_err(QueueRunnerError::CommitTransaction)?;
603
604 if leader != self.am_i_leader {
606 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 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 let txn = self
630 .listener
631 .begin()
632 .await
633 .map_err(QueueRunnerError::StartTransaction)?;
634
635 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 let schedules_status = repo.queue_schedule().list().await?;
668
669 let now = clock.now();
670 for schedule in &self.schedules {
671 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 if let Some(next_time) = status.last_scheduled_at {
685 if next_time > now {
686 continue;
688 }
689
690 if status.last_scheduled_job_completed == Some(false) {
691 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 repo.queue_worker()
720 .shutdown_dead_workers(clock, Duration::minutes(2))
721 .await?;
722
723 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 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 pub async fn process_all_jobs_in_tests(&mut self) -> Result<(), QueueRunnerError> {
754 self.setup_schedules().await?;
756
757 self.am_i_leader = true;
759
760 self.perform_leader_duties().await?;
763
764 let clock = self.state.clock();
765 let mut rng = self.state.rng();
766
767 let txn = self
769 .listener
770 .begin()
771 .await
772 .map_err(QueueRunnerError::StartTransaction)?;
773 let mut repo = PgRepository::from_conn(txn);
774
775 let queues = self.tracker.queues();
777 let jobs = repo
778 .queue_job()
779 .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
818struct JobTracker {
823 factories: HashMap<&'static str, JobFactory>,
825
826 running_jobs: JoinSet<JobResult>,
828
829 job_contexts: HashMap<tokio::task::Id, JobContext>,
831
832 last_join_result: Option<Result<(tokio::task::Id, JobResult), tokio::task::JoinError>>,
835
836 job_processing_time: Histogram<u64>,
838
839 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 fn queues(&self) -> Vec<&'static str> {
869 self.factories.keys().copied().collect()
870 }
871
872 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 let job = factory.expect("unknown job factory")(payload);
884
885 let timeout = job.timeout();
886 if let Some(timeout) = timeout {
889 let context = context.clone();
890
891 tokio::spawn(
894 context
895 .cancellation_token
896 .clone()
897 .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 context.cancellation_token.cancel();
923
924 let Some(context_stats) =
925 LogContext::maybe_with(mas_context::LogContext::stats)
926 else {
927 panic!("Missing log context, this should never happen");
930 };
931
932 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 fn has_jobs(&self) -> bool {
1001 !self.running_jobs.is_empty()
1002 }
1003
1004 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 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 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 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 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 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 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}