async def run_job(self, job: jobs.Job) -> None:
task_name = job.task_name
task = self.load_task(task_name=task_name)
# We store the log context in self. This way, when requesting
# a stop, we can get details on the currently running task
# in the logs.
start_time = time.time()
log_context = self.log_context = job.get_context()
log_context["start_timestamp"] = time.time()
logger.info("Starting job", extra={"action": "start_job", "job": log_context})
try:
task_result = task(**job.task_kwargs)
if asyncio.iscoroutine(task_result):
task_result = await task_result
except Exception as e:
task_result = None
log_title = "Job error"
log_action = "job_error"
log_level = logging.ERROR
exc_info = True
retry_exception = task.get_retry_exception(job)
if retry_exception:
raise retry_exception from e
raise exceptions.JobError() from e
else:
log_title = "Job success"
log_action = "job_success"
log_level = logging.INFO
exc_info = False
finally:
end_time = log_context["end_timestamp"] = time.time()
log_context["duration_seconds"] = end_time - start_time
extra = {"action": log_action, "job": log_context, "result": task_result}
logger.log(log_level, log_title, extra=extra, exc_info=exc_info)
await test_worker.run()
single_worker.assert_called()
assert caplog.messages == [
"Starting worker on all queues",
"Stopped worker on all queues",
]
@pytest.mark.parametrize(
"side_effect, status",
[
(None, "succeeded"),
(exceptions.JobError(), "failed"),
(exceptions.TaskNotFound(), "failed"),
],
)
async def test_process_job(mocker, test_worker, job_factory, connector,
side_effect, status):
async def coro(*args, **kwargs):
pass
test_worker.run_job = mocker.Mock(side_effect=side_effect or coro)
job = job_factory(id=1)
await test_worker.job_store.defer_job(job)
await test_worker.process_job(job=job)
test_worker.run_job.assert_called_with(
async def run_job(self, job: jobs.Job, worker_id: int) -> None:
task_name = job.task_name
task = self.load_task(task_name=task_name, worker_id=worker_id)
context = self.context_for_worker(worker_id=worker_id, task=task)
start_time = context.additional_context["start_timestamp"] = time.time(
)
self.logger.info(
f"Starting job {job.call_string}",
extra=context.log_extra(action="start_job"),
)
exc_info: Union[bool, Exception]
job_args = []
if task.pass_context:
job_args.append(context)
try:
task_result = task(*job_args, **job.task_kwargs)
if asyncio.iscoroutine(task_result):
task_result = await task_result
elif self.concurrency != 1:
logger.warning(
"When using worker concurrency, non-async tasks will block "
"the whole worker.",
extra=context.log_extra(action="concurrent_sync_task"),
)
except Exception as e:
task_result = None
log_title = "Error"
log_action = "job_error"
log_level = logging.ERROR
exc_info = e
retry_exception = task.get_retry_exception(exception=e, job=job)
if retry_exception:
log_title = "Error, to retry"
log_action = "job_error_retry"
raise retry_exception from e
raise exceptions.JobError() from e
else:
log_title = "Success"
log_action = "job_success"
log_level = logging.INFO
exc_info = False
finally:
end_time = time.time()
duration = end_time - start_time
context.additional_context.update({
"end_timestamp": end_time,
"duration": duration,
"result": task_result,
})
extra = context.log_extra(action=log_action)
text = (f"Job {job.call_string} ended with status: {log_title}, "
f"lasted {duration:.3f} s")
if task_result:
text += f" - Result: {task_result}"[:250]
self.logger.log(log_level, text, extra=extra, exc_info=exc_info)
await test_worker.run()
single_worker.assert_called()
assert set(caplog.messages) == {
"Starting worker on all queues",
"Stopped worker on all queues",
"No periodic task found, periodic deferrer will not run.",
}
@pytest.mark.parametrize(
"side_effect, status",
[
(None, "succeeded"),
(exceptions.JobError(), "failed"),
(exceptions.TaskNotFound(), "failed"),
],
)
async def test_process_job(mocker, test_worker, job_factory, connector,
side_effect, status):
async def coro(*args, **kwargs):
pass
test_worker.run_job = mocker.Mock(side_effect=side_effect or coro)
job = job_factory(id=1)
await test_worker.job_manager.defer_job_async(job)
await test_worker.process_job(job=job)
test_worker.run_job.assert_called_with(job=job, worker_id=0)