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 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 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
167const 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
174const MAX_CONCURRENT_JOBS: usize = 10;
176
177const MAX_JOBS_TO_FETCH: usize = 5;
179
180const MAX_ATTEMPTS: usize = 10;
182
183fn 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
195struct 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 listener
252 .listen("queue_leader_stepdown")
253 .await
254 .map_err(QueueRunnerError::SetupListener)?;
255
256 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 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 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 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 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 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 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 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 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 self.tracker
453 .process_jobs(&mut rng, clock, &mut repo, true)
454 .await?;
455
456 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 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 let txn = self
529 .listener
530 .begin()
531 .await
532 .map_err(QueueRunnerError::StartTransaction)?;
533 let mut repo = PgRepository::from_conn(txn);
534
535 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 repo.queue_worker()
547 .remove_leader_lease_if_expired(clock)
548 .await?;
549
550 let leader = repo
552 .queue_worker()
553 .try_get_leader_lease(clock, &self.registration)
554 .await?;
555
556 self.tracker
558 .process_jobs(&mut rng, clock, &mut repo, false)
559 .await?;
560
561 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 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 repo.into_inner()
602 .commit()
603 .await
604 .map_err(QueueRunnerError::CommitTransaction)?;
605
606 if leader != self.am_i_leader {
608 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 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 let txn = self
632 .listener
633 .begin()
634 .await
635 .map_err(QueueRunnerError::StartTransaction)?;
636
637 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 let schedules_status = repo.queue_schedule().list().await?;
670
671 let now = clock.now();
672 for schedule in &self.schedules {
673 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 if let Some(next_time) = status.last_scheduled_at {
687 if next_time > now {
688 continue;
690 }
691
692 if status.last_scheduled_job_completed == Some(false) {
693 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 repo.queue_worker()
722 .shutdown_dead_workers(clock, Duration::minutes(2))
723 .await?;
724
725 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 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 pub async fn process_all_jobs_in_tests(&mut self) -> Result<(), QueueRunnerError> {
756 self.setup_schedules().await?;
758
759 self.am_i_leader = true;
761
762 self.perform_leader_duties().await?;
765
766 let clock = self.state.clock();
767 let mut rng = self.state.rng();
768
769 let txn = self
771 .listener
772 .begin()
773 .await
774 .map_err(QueueRunnerError::StartTransaction)?;
775 let mut repo = PgRepository::from_conn(txn);
776
777 let queues = self.tracker.queues();
779 let jobs = repo
780 .queue_job()
781 .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
820struct JobTracker {
825 factories: HashMap<&'static str, JobFactory>,
827
828 running_jobs: JoinSet<JobResult>,
830
831 job_contexts: HashMap<tokio::task::Id, JobContext>,
833
834 last_join_result: Option<Result<(tokio::task::Id, JobResult), tokio::task::JoinError>>,
837
838 job_processing_time: Histogram<u64>,
840
841 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 fn queues(&self) -> Vec<&'static str> {
871 self.factories.keys().copied().collect()
872 }
873
874 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 let span = context.span();
884 async move {
885 let job = factory.expect("unknown job factory")(payload);
888
889 let timeout = job.timeout();
890 if let Some(timeout) = timeout {
893 let context = context.clone();
894
895 tokio::spawn(
898 context
899 .cancellation_token
900 .clone()
901 .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 context.cancellation_token.cancel();
927
928 let Some(context_stats) =
929 LogContext::maybe_with(mas_context::LogContext::stats)
930 else {
931 panic!("Missing log context, this should never happen");
934 };
935
936 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 fn has_jobs(&self) -> bool {
1006 !self.running_jobs.is_empty()
1007 }
1008
1009 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 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 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 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 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 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 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}