async def test_deserialize_job_raw(): assert deserialize_job_raw( pickle.dumps({ 'f': 1, 'a': 2, 'k': 3, 't': 4, 'et': 5 })) == (1, 2, 3, 4, 5) with pytest.raises(DeserializationError, match='unable to deserialize job'): deserialize_job_raw(b'123')
async def run_job(self, job_id: str, score: int) -> None: # noqa: C901 start_ms = timestamp_ms() coros = ( self.pool.get(job_key_prefix + job_id, encoding=None), self.pool.incr(retry_key_prefix + job_id), self.pool.expire(retry_key_prefix + job_id, 88400), ) if self.allow_abort_jobs: abort_job, v, job_try, _ = await asyncio.gather( self.pool.zrem(abort_jobs_ss, job_id), *coros) else: v, job_try, _ = await asyncio.gather(*coros) abort_job = False function_name, enqueue_time_ms = '<unknown>', 0 args: Tuple[Any, ...] = () kwargs: Dict[Any, Any] = {} async def job_failed(exc: BaseException) -> None: self.jobs_failed += 1 result_data_ = serialize_result( function=function_name, args=args, kwargs=kwargs, job_try=job_try, enqueue_time_ms=enqueue_time_ms, success=False, result=exc, start_ms=start_ms, finished_ms=timestamp_ms(), ref=f'{job_id}:{function_name}', serializer=self.job_serializer, queue_name=self.queue_name, ) await asyncio.shield(self.finish_failed_job(job_id, result_data_)) if not v: logger.warning('job %s expired', job_id) return await job_failed(JobExecutionFailed('job expired')) try: function_name, args, kwargs, enqueue_job_try, enqueue_time_ms = deserialize_job_raw( v, deserializer=self.job_deserializer) except SerializationError as e: logger.exception('deserializing job %s failed', job_id) return await job_failed(e) if abort_job: t = (timestamp_ms() - enqueue_time_ms) / 1000 logger.info('%6.2fs ⊘ %s:%s aborted before start', t, job_id, function_name) return await job_failed(asyncio.CancelledError()) try: function: Union[Function, CronJob] = self.functions[function_name] except KeyError: logger.warning('job %s, function %r not found', job_id, function_name) return await job_failed( JobExecutionFailed(f'function {function_name!r} not found')) if hasattr(function, 'next_run'): # cron_job ref = function_name keep_in_progress: Optional[float] = keep_cronjob_progress else: ref = f'{job_id}:{function_name}' keep_in_progress = None if enqueue_job_try and enqueue_job_try > job_try: job_try = enqueue_job_try await self.pool.setex(retry_key_prefix + job_id, 88400, str(job_try)) max_tries = self.max_tries if function.max_tries is None else function.max_tries if job_try > max_tries: t = (timestamp_ms() - enqueue_time_ms) / 1000 logger.warning('%6.2fs ! %s max retries %d exceeded', t, ref, max_tries) self.jobs_failed += 1 result_data = serialize_result( function_name, args, kwargs, job_try, enqueue_time_ms, False, JobExecutionFailed(f'max {max_tries} retries exceeded'), start_ms, timestamp_ms(), ref, self.queue_name, serializer=self.job_serializer, ) return await asyncio.shield( self.finish_failed_job(job_id, result_data)) result = no_result exc_extra = None finish = False timeout_s = self.job_timeout_s if function.timeout_s is None else function.timeout_s incr_score: Optional[int] = None job_ctx = { 'job_id': job_id, 'job_try': job_try, 'enqueue_time': ms_to_datetime(enqueue_time_ms), 'score': score, } ctx = {**self.ctx, **job_ctx} start_ms = timestamp_ms() success = False try: s = args_to_string(args, kwargs) extra = f' try={job_try}' if job_try > 1 else '' if (start_ms - score) > 1200: extra += f' delayed={(start_ms - score) / 1000:0.2f}s' logger.info('%6.2fs → %s(%s)%s', (start_ms - enqueue_time_ms) / 1000, ref, s, extra) self.job_tasks[job_id] = task = self.loop.create_task( function.coroutine(ctx, *args, **kwargs)) cancel_handler = self.loop.call_at(self.loop.time() + timeout_s, task.cancel) # run repr(result) and extra inside try/except as they can raise exceptions try: result = await task except (Exception, asyncio.CancelledError) as e: exc_extra = getattr(e, 'extra', None) if callable(exc_extra): exc_extra = exc_extra() raise else: result_str = '' if result is None else truncate(repr(result)) finally: del self.job_tasks[job_id] cancel_handler.cancel() except (Exception, asyncio.CancelledError) as e: finished_ms = timestamp_ms() t = (finished_ms - start_ms) / 1000 if self.retry_jobs and isinstance(e, Retry): incr_score = e.defer_score logger.info('%6.2fs ↻ %s retrying job in %0.2fs', t, ref, (e.defer_score or 0) / 1000) if e.defer_score: incr_score = e.defer_score + (timestamp_ms() - score) self.jobs_retried += 1 elif job_id in self.aborting_tasks and isinstance( e, asyncio.CancelledError): logger.info('%6.2fs ⊘ %s aborted', t, ref) result = e finish = True self.aborting_tasks.remove(job_id) self.jobs_failed += 1 elif self.retry_jobs and isinstance( e, (asyncio.CancelledError, RetryJob)): logger.info('%6.2fs ↻ %s cancelled, will be run again', t, ref) self.jobs_retried += 1 else: logger.exception('%6.2fs ! %s failed, %s: %s', t, ref, e.__class__.__name__, e, extra={'extra': exc_extra}) result = e finish = True self.jobs_failed += 1 else: success = True finished_ms = timestamp_ms() logger.info('%6.2fs ← %s ● %s', (finished_ms - start_ms) / 1000, ref, result_str) finish = True self.jobs_complete += 1 keep_result_forever = (self.keep_result_forever if function.keep_result_forever is None else function.keep_result_forever) result_timeout_s = self.keep_result_s if function.keep_result_s is None else function.keep_result_s result_data = None if result is not no_result and (keep_result_forever or result_timeout_s > 0): result_data = serialize_result( function_name, args, kwargs, job_try, enqueue_time_ms, success, result, start_ms, finished_ms, ref, self.queue_name, serializer=self.job_serializer, ) await asyncio.shield( self.finish_job( job_id, finish, result_data, result_timeout_s, keep_result_forever, incr_score, keep_in_progress, ))
async def run_job(self, job_id, score): # noqa: C901 start_ms = timestamp_ms() v, job_try, _ = await asyncio.gather( self.pool.get(job_key_prefix + job_id, encoding=None), self.pool.incr(retry_key_prefix + job_id), self.pool.expire(retry_key_prefix + job_id, 88400), ) function_name, args, kwargs, enqueue_time_ms = '<unknown>', (), {}, 0 async def job_failed(exc: Exception): self.jobs_failed += 1 result_data_ = serialize_result( function=function_name, args=args, kwargs=kwargs, job_try=job_try, enqueue_time_ms=enqueue_time_ms, success=False, result=exc, start_ms=start_ms, finished_ms=timestamp_ms(), ref=f'{job_id}:{function_name}', serializer=self.job_serializer, ) await asyncio.shield(self.abort_job(job_id, result_data_)) if not v: logger.warning('job %s expired', job_id) return await job_failed(JobExecutionFailed('job expired')) try: function_name, args, kwargs, enqueue_job_try, enqueue_time_ms = deserialize_job_raw( v, deserializer=self.job_deserializer ) except SerializationError as e: logger.exception('deserializing job %s failed', job_id) return await job_failed(e) try: function: Union[Function, CronJob] = self.functions[function_name] except KeyError: logger.warning('job %s, function %r not found', job_id, function_name) return await job_failed(JobExecutionFailed(f'function {function_name!r} not found')) if hasattr(function, 'next_run'): # cron_job ref = function_name else: ref = f'{job_id}:{function_name}' if enqueue_job_try and enqueue_job_try > job_try: job_try = enqueue_job_try await self.pool.setex(retry_key_prefix + job_id, 88400, str(job_try)) max_tries = self.max_tries if function.max_tries is None else function.max_tries if job_try > max_tries: t = (timestamp_ms() - enqueue_time_ms) / 1000 logger.warning('%6.2fs ! %s max retries %d exceeded', t, ref, max_tries) self.jobs_failed += 1 result_data = serialize_result( function_name, args, kwargs, job_try, enqueue_time_ms, False, JobExecutionFailed(f'max {max_tries} retries exceeded'), start_ms, timestamp_ms(), ref, serializer=self.job_serializer, ) return await asyncio.shield(self.abort_job(job_id, result_data)) result = no_result exc_extra = None finish = False timeout_s = self.job_timeout_s if function.timeout_s is None else function.timeout_s incr_score = None job_ctx = { 'job_id': job_id, 'job_try': job_try, 'enqueue_time': ms_to_datetime(enqueue_time_ms), 'score': score, } ctx = {**self.ctx, **job_ctx} start_ms = timestamp_ms() success = False try: s = args_to_string(args, kwargs) extra = f' try={job_try}' if job_try > 1 else '' if (start_ms - score) > 1200: extra += f' delayed={(start_ms - score) / 1000:0.2f}s' logger.info('%6.2fs → %s(%s)%s', (start_ms - enqueue_time_ms) / 1000, ref, s, extra) # run repr(result) and extra inside try/except as they can raise exceptions try: async with async_timeout.timeout(timeout_s): result = await function.coroutine(ctx, *args, **kwargs) except Exception as e: exc_extra = getattr(e, 'extra', None) if callable(exc_extra): exc_extra = exc_extra() raise else: result_str = '' if result is None else truncate(repr(result)) except Exception as e: finished_ms = timestamp_ms() t = (finished_ms - start_ms) / 1000 if self.retry_jobs and isinstance(e, Retry): incr_score = e.defer_score logger.info('%6.2fs ↻ %s retrying job in %0.2fs', t, ref, (e.defer_score or 0) / 1000) if e.defer_score: incr_score = e.defer_score + (timestamp_ms() - score) self.jobs_retried += 1 elif self.retry_jobs and isinstance(e, asyncio.CancelledError): logger.info('%6.2fs ↻ %s cancelled, will be run again', t, ref) self.jobs_retried += 1 else: logger.exception( '%6.2fs ! %s failed, %s: %s', t, ref, e.__class__.__name__, e, extra={'extra': exc_extra} ) result = e finish = True self.jobs_failed += 1 else: success = True finished_ms = timestamp_ms() logger.info('%6.2fs ← %s ● %s', (finished_ms - start_ms) / 1000, ref, result_str) finish = True self.jobs_complete += 1 result_timeout_s = self.keep_result_s if function.keep_result_s is None else function.keep_result_s result_data = None if result is not no_result and result_timeout_s > 0: result_data = serialize_result( function_name, args, kwargs, job_try, enqueue_time_ms, success, result, start_ms, finished_ms, ref, serializer=self.job_serializer, ) await asyncio.shield(self.finish_job(job_id, finish, result_data, result_timeout_s, incr_score))