Skip to main content

cja/jobs/
worker.rs

1use std::time::Duration;
2
3use thiserror::Error;
4use tokio_util::sync::CancellationToken;
5use tracing::Span;
6
7use crate::app_state::AppState as AS;
8
9use super::registry::JobRegistry;
10
11/// Default maximum number of retry attempts before a job is moved to the dead letter queue.
12///
13/// With exponential backoff (`2^(error_count+1)` seconds), 20 retries means:
14/// - First retry after 2 seconds
15/// - Last retry after ~6 days
16/// - Total retry window of ~12 days
17pub const DEFAULT_MAX_RETRIES: i32 = 20;
18
19/// Default lock timeout duration (2 hours).
20///
21/// Jobs locked for longer than this duration will be considered abandoned and
22/// made available for other workers to pick up. This handles cases where a worker
23/// crashes or becomes unresponsive while processing a job.
24pub const DEFAULT_LOCK_TIMEOUT: Duration = Duration::from_hours(2);
25
26pub(super) type RunJobResult = Result<RunJobSuccess, JobError>;
27
28#[derive(Debug)]
29pub(super) struct RunJobSuccess(JobFromDB);
30
31#[derive(Debug, sqlx::FromRow)]
32pub struct JobFromDB {
33    pub job_id: uuid::Uuid,
34    pub name: String,
35    pub payload: serde_json::Value,
36    pub priority: i32,
37    pub run_at: chrono::DateTime<chrono::Utc>,
38    pub created_at: chrono::DateTime<chrono::Utc>,
39    pub context: String,
40    pub error_count: i32,
41    pub last_error_message: Option<String>,
42    pub last_failed_at: Option<chrono::DateTime<chrono::Utc>>,
43}
44
45#[derive(Debug, Error)]
46#[error("JobError(id:${}) ${1}", self.0.job_id)]
47pub(crate) struct JobError(JobFromDB, color_eyre::Report);
48
49struct Worker<AppState: AS, R: JobRegistry<AppState>> {
50    id: uuid::Uuid,
51    state: AppState,
52    registry: R,
53    sleep_duration: Duration,
54    max_retries: i32,
55    cancellation_token: CancellationToken,
56    lock_timeout: Duration,
57}
58
59impl<AppState: AS, R: JobRegistry<AppState>> Worker<AppState, R> {
60    fn new(
61        state: AppState,
62        registry: R,
63        sleep_duration: Duration,
64        max_retries: i32,
65        cancellation_token: CancellationToken,
66        lock_timeout: Duration,
67    ) -> Self {
68        Self {
69            id: uuid::Uuid::new_v4(),
70            state,
71            registry,
72            sleep_duration,
73            max_retries,
74            cancellation_token,
75            lock_timeout,
76        }
77    }
78
79    #[tracing::instrument(
80        name = "worker.run_job",
81        skip(self, job),
82        fields(
83            job.id = %job.job_id,
84            job.name = job.name,
85            job.priority = job.priority,
86            job.run_at = %job.run_at,
87            job.created_at = %job.created_at,
88            job.context = job.context,
89            job.error_count = job.error_count,
90            worker.id = %self.id,
91        )
92        err,
93    )]
94    async fn run_job(&self, job: &JobFromDB) -> color_eyre::Result<()> {
95        self.registry
96            .run_job(job, self.state.clone(), self.cancellation_token.clone())
97            .await
98    }
99
100    pub(crate) async fn run_next_job(&self, job: JobFromDB) -> color_eyre::Result<RunJobResult> {
101        let job_result = self.run_job(&job).await;
102
103        if let Err(e) = job_result {
104            // Extract error message from color_eyre::Report
105            let error_message = format!("{e}");
106
107            // Check if job has exceeded max retries
108            if job.error_count >= self.max_retries {
109                // Move job to dead letter queue
110                tracing::error!(
111                    worker.id = %self.id,
112                    job_id = %job.job_id,
113                    error_count = job.error_count,
114                    max_retries = self.max_retries,
115                    "Job permanently failed - moved to dead letter queue"
116                );
117
118                let mut tx = self.state.db().begin().await?;
119
120                sqlx::query(
121                    "INSERT INTO dead_letter_jobs (original_job_id, name, payload, context, priority, error_count, last_error_message, created_at)
122                     VALUES ($1, $2, $3, $4, $5, $6, $7, $8)",
123                )
124                .bind(job.job_id)
125                .bind(&job.name)
126                .bind(&job.payload)
127                .bind(&job.context)
128                .bind(job.priority)
129                .bind(job.error_count)
130                .bind(&error_message)
131                .bind(job.created_at)
132                .execute(&mut *tx)
133                .await?;
134
135                sqlx::query("DELETE FROM jobs WHERE job_id = $1 AND locked_by = $2")
136                    .bind(job.job_id)
137                    .bind(self.id.to_string())
138                    .execute(&mut *tx)
139                    .await?;
140
141                tx.commit().await?;
142
143                return Ok(Err(JobError(job, e)));
144            }
145
146            // Job is under max retries - requeue with exponential backoff
147            tracing::warn!(
148                worker.id = %self.id,
149                job_id = %job.job_id,
150                error_count = job.error_count,
151                retry_attempt = job.error_count + 1,
152                "Job failed, retry #{}",
153                job.error_count + 1
154            );
155
156            sqlx::query(
157                "
158                UPDATE jobs
159                SET locked_by = NULL,
160                    locked_at = NULL,
161                    error_count = error_count + 1,
162                    last_error_message = $3,
163                    last_failed_at = NOW(),
164                    run_at = NOW() + (POWER(2, error_count + 1)) * interval '1 second'
165                WHERE job_id = $1 AND locked_by = $2
166                ",
167            )
168            .bind(job.job_id)
169            .bind(self.id.to_string())
170            .bind(error_message)
171            .execute(self.state.db())
172            .await?;
173
174            return Ok(Err(JobError(job, e)));
175        }
176
177        sqlx::query(
178            "
179                DELETE FROM jobs
180                WHERE job_id = $1 AND locked_by = $2
181                ",
182        )
183        .bind(job.job_id)
184        .bind(self.id.to_string())
185        .execute(self.state.db())
186        .await?;
187
188        Ok(Ok(RunJobSuccess(job)))
189    }
190
191    #[tracing::instrument(
192        name = "worker.fetch_next_job",
193        level = "trace",
194        skip(self),
195        fields(
196            worker.id = %self.id,
197            job.id,
198            job.name,
199            lock_timeout_secs = self.lock_timeout.as_secs(),
200        ),
201        err,
202    )]
203    #[allow(clippy::cast_possible_wrap)]
204    async fn fetch_next_job(&self) -> color_eyre::Result<Option<JobFromDB>> {
205        // Cast is safe: lock timeouts are typically hours, not approaching i64::MAX seconds
206        let lock_timeout_secs = self.lock_timeout.as_secs() as i64;
207
208        let job = sqlx::query_as::<_, JobFromDB>(
209            "
210            UPDATE jobs
211            SET LOCKED_BY = $1, LOCKED_AT = NOW()
212            WHERE job_id = (
213                SELECT job_id
214                FROM jobs
215                WHERE run_at <= NOW()
216                  AND (
217                    locked_by IS NULL
218                    OR locked_at < NOW() - ($2 || ' seconds')::interval
219                  )
220                ORDER BY priority DESC, run_at ASC, created_at ASC
221                LIMIT 1
222                FOR UPDATE SKIP LOCKED
223            )
224            RETURNING job_id, name, payload, priority, run_at, created_at, context, error_count, last_error_message, last_failed_at
225            ",
226        )
227        .bind(self.id.to_string())
228        .bind(lock_timeout_secs.to_string())
229        .fetch_optional(self.state.db())
230        .await?;
231
232        if let Some(job) = &job {
233            let span = Span::current();
234            span.record("job.id", job.job_id.to_string());
235            span.record("job.name", &job.name);
236        }
237
238        Ok(job)
239    }
240
241    #[tracing::instrument(
242        name = "worker.tick",
243        level = "trace",
244        skip(self),
245        fields(
246            worker.id = %self.id,
247        ),
248    )]
249    async fn tick(&self) -> color_eyre::Result<()> {
250        let job = self.fetch_next_job().await?;
251
252        let Some(job) = job else {
253            let duration = self.sleep_duration;
254            tracing::debug!(worker.id =% self.id, ?duration, "No Job to Run, sleeping for requested duration");
255
256            tokio::time::sleep(duration).await;
257
258            return Ok(());
259        };
260
261        let result = self.run_next_job(job).await?;
262
263        match result {
264            Ok(RunJobSuccess(job)) => {
265                tracing::info!(worker.id =% self.id, job_id =% job.job_id, "Job Ran");
266            }
267            Err(job_error) => {
268                tracing::error!(
269                    worker.id =% self.id,
270                    job_id =% job_error.0.job_id,
271                    error_count =% job_error.0.error_count,
272                    error_msg =% job_error.1,
273                    "Job Errored"
274                );
275            }
276        }
277
278        Ok(())
279    }
280}
281
282/// Release database locks held by a worker.
283///
284/// This should be called during graceful shutdown to immediately release any job locks
285/// held by this worker, rather than waiting for the 2-hour lock timeout.
286async fn cleanup_worker_locks<AppState: AS, R: JobRegistry<AppState>>(
287    worker: &Worker<AppState, R>,
288) -> color_eyre::Result<()> {
289    tracing::info!(worker_id = %worker.id, "Releasing database locks");
290
291    let result = sqlx::query(
292        "UPDATE jobs
293         SET locked_by = NULL, locked_at = NULL
294         WHERE locked_by = $1",
295    )
296    .bind(worker.id.to_string())
297    .execute(worker.state.db())
298    .await?;
299
300    tracing::info!(
301        worker_id = %worker.id,
302        locks_released = result.rows_affected(),
303        "Database locks released"
304    );
305
306    Ok(())
307}
308
309/// Start a job worker that processes jobs from the queue.
310///
311/// The worker will continuously poll for jobs and execute them using the provided registry.
312/// Jobs are executed with automatic retry logic on failure.
313///
314/// # Arguments
315///
316/// * `app_state` - The application state containing database connection and configuration
317/// * `registry` - The job registry that maps job names to their implementations
318/// * `sleep_duration` - How long to sleep when no jobs are available
319/// * `max_retries` - Maximum number of times to retry a failed job before moving to the dead letter queue (default: 20)
320/// * `shutdown_token` - Cancellation token for graceful shutdown. When cancelled, the worker
321///   will stop accepting new jobs and release database locks before exiting.
322/// * `lock_timeout` - How long a job can be locked before it's considered abandoned and
323///   becomes available for other workers (default: 2 hours)
324///
325/// # Retry Behavior
326///
327/// When a job fails:
328/// - The error count is incremented
329/// - The error message and timestamp are recorded
330/// - The job is requeued with exponential backoff: delay = `2^(error_count + 1)` seconds
331///   (first retry: 2s, second: 4s, third: 8s, fourth: 16s, etc.)
332/// - If `error_count` >= `max_retries`, the job is moved to the dead letter queue
333///
334/// # Graceful Shutdown
335///
336/// When the `shutdown_token` is cancelled:
337/// - The worker stops polling for new jobs
338/// - Any currently executing job is allowed to complete
339/// - Database locks are released immediately (instead of waiting for the lock timeout)
340///
341/// # Lock Timeout
342///
343/// If a worker crashes or becomes unresponsive while processing a job, the job will remain
344/// locked in the database. The `lock_timeout` parameter controls how long to wait before
345/// considering such jobs abandoned. After the timeout expires, any worker can pick up the
346/// job and retry it.
347///
348/// # Example
349///
350/// ```ignore
351/// use std::time::Duration;
352/// use tokio_util::sync::CancellationToken;
353///
354/// let shutdown_token = CancellationToken::new();
355/// let worker_token = shutdown_token.clone();
356///
357/// // Start worker with graceful shutdown support and lock timeout
358/// tokio::spawn(async move {
359///     cja::jobs::worker::job_worker(
360///         app_state,
361///         registry,
362///         Duration::from_secs(60),      // poll every 60s when idle
363///         20,                            // max 20 retries
364///         worker_token,                  // for graceful shutdown
365///         Duration::from_secs(2 * 3600), // 2 hour lock timeout
366///     ).await.unwrap();
367/// });
368///
369/// // Later, trigger shutdown
370/// shutdown_token.cancel();
371/// ```
372pub async fn job_worker<AppState: AS>(
373    app_state: AppState,
374    registry: impl JobRegistry<AppState>,
375    sleep_duration: Duration,
376    max_retries: i32,
377    shutdown_token: CancellationToken,
378    lock_timeout: Duration,
379) -> color_eyre::Result<()> {
380    let worker = Worker::new(
381        app_state,
382        registry,
383        sleep_duration,
384        max_retries,
385        shutdown_token.clone(),
386        lock_timeout,
387    );
388
389    loop {
390        tokio::select! {
391            result = worker.tick() => {
392                result?;
393            }
394            () = shutdown_token.cancelled() => {
395                tracing::info!(worker_id = %worker.id, "Job worker shutdown requested");
396                break;
397            }
398        }
399    }
400
401    cleanup_worker_locks(&worker).await?;
402    tracing::info!(worker_id = %worker.id, "Job worker shutdown complete");
403    Ok(())
404}
405
406#[cfg(test)]
407mod tests {
408    use super::*;
409    use crate::app_state::AppState;
410    use crate::impl_job_registry;
411    use crate::jobs::Job;
412    use crate::server::cookies::CookieKey;
413
414    #[derive(Clone)]
415    struct TestAppState {
416        db: sqlx::PgPool,
417        cookie_key: CookieKey,
418    }
419
420    impl AppState for TestAppState {
421        fn db(&self) -> &sqlx::PgPool {
422            &self.db
423        }
424
425        fn version(&self) -> &'static str {
426            "test"
427        }
428
429        fn cookie_key(&self) -> &CookieKey {
430            &self.cookie_key
431        }
432    }
433
434    #[derive(Clone, Debug, serde::Deserialize, serde::Serialize)]
435    struct TestJob {
436        id: String,
437    }
438
439    #[async_trait::async_trait]
440    impl Job<TestAppState> for TestJob {
441        const NAME: &'static str = "TestJob";
442
443        async fn run(&self, _app_state: TestAppState) -> color_eyre::Result<()> {
444            Ok(())
445        }
446    }
447
448    impl_job_registry!(TestAppState, TestJob);
449
450    /// Test that `fetch_next_job` picks up a job with a stale lock (lock older than timeout)
451    #[sqlx::test]
452    async fn test_fetch_next_job_picks_up_stale_locked_job(db: sqlx::PgPool) {
453        let app_state = TestAppState {
454            db: db.clone(),
455            cookie_key: CookieKey::generate(),
456        };
457
458        let job_id = uuid::Uuid::new_v4();
459        let stale_worker_id = "crashed-worker";
460
461        // Insert a job locked 120 seconds ago
462        sqlx::query(
463            "INSERT INTO jobs (job_id, name, payload, priority, run_at, created_at, context, error_count, locked_by, locked_at)
464             VALUES ($1, $2, $3, $4, NOW(), NOW(), $5, $6, $7, NOW() - interval '120 seconds')",
465        )
466        .bind(job_id)
467        .bind("TestJob")
468        .bind(serde_json::json!({"id": "stale-lock-test"}))
469        .bind(0)
470        .bind("test-stale-lock")
471        .bind(0)
472        .bind(stale_worker_id)
473        .execute(&db)
474        .await
475        .unwrap();
476
477        // Create a worker with 60 second lock timeout
478        let worker = Worker::new(
479            app_state,
480            Jobs,
481            Duration::from_secs(1),
482            20,
483            CancellationToken::new(),
484            Duration::from_mins(1), // 60 second timeout
485        );
486
487        // fetch_next_job should pick up the stale locked job
488        let fetched = worker.fetch_next_job().await.unwrap();
489        assert!(fetched.is_some());
490        assert_eq!(fetched.unwrap().job_id, job_id);
491    }
492
493    /// Test that `fetch_next_job` does NOT pick up a job with a fresh lock
494    #[sqlx::test]
495    async fn test_fetch_next_job_skips_recently_locked_job(db: sqlx::PgPool) {
496        let app_state = TestAppState {
497            db: db.clone(),
498            cookie_key: CookieKey::generate(),
499        };
500
501        let job_id = uuid::Uuid::new_v4();
502        let active_worker_id = "active-worker";
503
504        // Insert a job locked only 10 seconds ago
505        sqlx::query(
506            "INSERT INTO jobs (job_id, name, payload, priority, run_at, created_at, context, error_count, locked_by, locked_at)
507             VALUES ($1, $2, $3, $4, NOW(), NOW(), $5, $6, $7, NOW() - interval '10 seconds')",
508        )
509        .bind(job_id)
510        .bind("TestJob")
511        .bind(serde_json::json!({"id": "recent-lock-test"}))
512        .bind(0)
513        .bind("test-recent-lock")
514        .bind(0)
515        .bind(active_worker_id)
516        .execute(&db)
517        .await
518        .unwrap();
519
520        // Create a worker with 1 hour lock timeout
521        let worker = Worker::new(
522            app_state,
523            Jobs,
524            Duration::from_secs(1),
525            20,
526            CancellationToken::new(),
527            Duration::from_hours(1), // 1 hour timeout
528        );
529
530        // fetch_next_job should NOT pick up the recently locked job
531        let fetched = worker.fetch_next_job().await.unwrap();
532        assert!(fetched.is_none());
533    }
534
535    /// Test that unlocked jobs are picked up before stale locked jobs (by priority)
536    #[sqlx::test]
537    async fn test_fetch_next_job_prefers_unlocked_by_priority(db: sqlx::PgPool) {
538        let app_state = TestAppState {
539            db: db.clone(),
540            cookie_key: CookieKey::generate(),
541        };
542
543        let unlocked_job_id = uuid::Uuid::new_v4();
544        let stale_locked_job_id = uuid::Uuid::new_v4();
545
546        // Insert unlocked job with higher priority
547        sqlx::query(
548            "INSERT INTO jobs (job_id, name, payload, priority, run_at, created_at, context, error_count)
549             VALUES ($1, $2, $3, $4, NOW(), NOW(), $5, $6)",
550        )
551        .bind(unlocked_job_id)
552        .bind("TestJob")
553        .bind(serde_json::json!({"id": "unlocked"}))
554        .bind(10) // Higher priority
555        .bind("test-unlocked")
556        .bind(0)
557        .execute(&db)
558        .await
559        .unwrap();
560
561        // Insert stale locked job with lower priority
562        sqlx::query(
563            "INSERT INTO jobs (job_id, name, payload, priority, run_at, created_at, context, error_count, locked_by, locked_at)
564             VALUES ($1, $2, $3, $4, NOW(), NOW(), $5, $6, $7, NOW() - interval '120 seconds')",
565        )
566        .bind(stale_locked_job_id)
567        .bind("TestJob")
568        .bind(serde_json::json!({"id": "stale-locked"}))
569        .bind(5) // Lower priority
570        .bind("test-stale")
571        .bind(0)
572        .bind("crashed-worker")
573        .execute(&db)
574        .await
575        .unwrap();
576
577        // Create a worker with 60 second lock timeout
578        let worker = Worker::new(
579            app_state,
580            Jobs,
581            Duration::from_secs(1),
582            20,
583            CancellationToken::new(),
584            Duration::from_mins(1),
585        );
586
587        // Should pick the higher priority unlocked job first
588        let fetched = worker.fetch_next_job().await.unwrap();
589        assert!(fetched.is_some());
590        assert_eq!(fetched.unwrap().job_id, unlocked_job_id);
591    }
592
593    /// Test that among same-priority jobs, the one that became eligible earliest
594    /// (smaller `run_at`) is picked first — even when a competing job has an older
595    /// `created_at`. This guards the readiness-ordering contract: a job whose
596    /// `run_at` was pushed into the future by retry backoff must not cut in front
597    /// of a job that has been due longer, just because it was enqueued earlier.
598    #[sqlx::test]
599    async fn test_fetch_next_job_orders_by_run_at_over_created_at(db: sqlx::PgPool) {
600        let app_state = TestAppState {
601            db: db.clone(),
602            cookie_key: CookieKey::generate(),
603        };
604
605        let older_created_later_run_id = uuid::Uuid::new_v4();
606        let newer_created_earlier_run_id = uuid::Uuid::new_v4();
607
608        // Job A: created earliest, but only became due 30 seconds ago (e.g. a
609        // job that failed and had its run_at pushed out by backoff).
610        sqlx::query(
611            "INSERT INTO jobs (job_id, name, payload, priority, run_at, created_at, context, error_count)
612             VALUES ($1, $2, $3, $4, NOW() - interval '30 seconds', NOW() - interval '300 seconds', $5, $6)",
613        )
614        .bind(older_created_later_run_id)
615        .bind("TestJob")
616        .bind(serde_json::json!({"id": "older-created-later-run"}))
617        .bind(0)
618        .bind("test-older-created")
619        .bind(0)
620        .execute(&db)
621        .await
622        .unwrap();
623
624        // Job B: created more recently, but has been due longer (smaller run_at).
625        sqlx::query(
626            "INSERT INTO jobs (job_id, name, payload, priority, run_at, created_at, context, error_count)
627             VALUES ($1, $2, $3, $4, NOW() - interval '120 seconds', NOW() - interval '60 seconds', $5, $6)",
628        )
629        .bind(newer_created_earlier_run_id)
630        .bind("TestJob")
631        .bind(serde_json::json!({"id": "newer-created-earlier-run"}))
632        .bind(0)
633        .bind("test-newer-created")
634        .bind(0)
635        .execute(&db)
636        .await
637        .unwrap();
638
639        let worker = Worker::new(
640            app_state,
641            Jobs,
642            Duration::from_secs(1),
643            20,
644            CancellationToken::new(),
645            Duration::from_mins(1),
646        );
647
648        // Both jobs share a priority; the one due longest (smaller run_at) wins,
649        // regardless of which was created first.
650        let fetched = worker.fetch_next_job().await.unwrap();
651        assert!(fetched.is_some());
652        assert_eq!(fetched.unwrap().job_id, newer_created_earlier_run_id);
653    }
654}