From 8fc987dc68615aec6ff956fdbb752616e2c19abb Mon Sep 17 00:00:00 2001 From: Wolfgang Langner Date: Wed, 30 Jan 2019 00:55:54 +0100 Subject: [PATCH] Make logging in worker consitent. (#1030) Switch some messages from warn to info because it is normal requested bahavior. --- rq/worker.py | 34 +++++++++++++++++----------------- tests/test_worker.py | 8 ++++---- 2 files changed, 21 insertions(+), 21 deletions(-) diff --git a/rq/worker.py b/rq/worker.py index bdb5a0f..506c8ab 100644 --- a/rq/worker.py +++ b/rq/worker.py @@ -430,7 +430,7 @@ class Worker(object): raise StopRequested() def handle_warm_shutdown_request(self): - self.log.warning('Warm shut down requested') + self.log.info('Warm shut down requested') def check_for_suspension(self, burst): """Check to see if workers have been suspended by `rq suspend`""" @@ -469,7 +469,7 @@ class Worker(object): self._install_signal_handlers() did_perform_work = False self.register_birth() - self.log.info("RQ worker {0!r} started, version {1}".format(self.key, VERSION)) + self.log.info("RQ worker %r started, version %s", self.key, VERSION) self.set_state(WorkerStatus.STARTED) qnames = self.queue_names() self.log.info('*** Listening on %s...', green(', '.join(qnames))) @@ -491,7 +491,7 @@ class Worker(object): result = self.dequeue_job_and_maintain_ttl(timeout) if result is None: if burst: - self.log.info("RQ worker {0!r} done, quitting".format(self.key)) + self.log.info("RQ worker %r done, quitting", self.key) break job, queue = result @@ -526,12 +526,12 @@ class Worker(object): job, queue = result if self.log_job_description: - self.log.info('{0}: {1} ({2})'.format(green(queue.name), - blue(job.description), - job.id)) + self.log.info('%s: %s (%s)', green(queue.name), + blue(job.description), + job.id) else: - self.log.info('{0}:{1}'.format(green(queue.name), - job.id)) + self.log.info('%s:%s', green(queue.name), + job.id) break except DequeueTimeout: @@ -652,9 +652,9 @@ class Worker(object): # Unhandled failure: move the job to the failed queue self.log.warning(( - 'Moving job to {0!r} queue ' - '(work-horse terminated unexpectedly; waitpid returned {1})' - ).format(self.failed_queue.name, ret_val)) + 'Moving job to %r queue ' + '(work-horse terminated unexpectedly; waitpid returned %s)' + ), self.failed_queue.name, ret_val) self.failed_queue.quarantine( job, exc_info=( @@ -827,7 +827,7 @@ class Worker(object): finally: pop_connection() - self.log.info('{0}: {1} ({2})'.format(green(job.origin), blue('Job OK'), job.id)) + self.log.info('%s: %s (%s)', green(job.origin), blue('Job OK'), job.id) if rv is not None: log_result = "{0!r}".format(as_text(text_type(rv))) self.log.debug('Result: %s', yellow(log_result)) @@ -837,9 +837,9 @@ class Worker(object): if result_ttl == 0: self.log.info('Result discarded immediately') elif result_ttl > 0: - self.log.info('Result is kept for {0} seconds'.format(result_ttl)) + self.log.info('Result is kept for %s seconds', result_ttl) else: - self.log.warning('Result will never expire, clean up result key manually') + self.log.info('Result will never expire, clean up result key manually') return True @@ -869,7 +869,7 @@ class Worker(object): def move_to_failed_queue(self, job, *exc_info): """Default exception handler: move the job to the failed queue.""" - self.log.warning('Moving job to {0!r} queue'.format(self.failed_queue.name)) + self.log.warning('Moving job to %r queue', self.failed_queue.name) from .handlers import move_to_failed_queue move_to_failed_queue(job, *exc_info) @@ -904,7 +904,7 @@ class Worker(object): def clean_registries(self): """Runs maintenance jobs on each Queue's registries.""" for queue in self.queues: - self.log.info('Cleaning registries for queue: {0}'.format(queue.name)) + self.log.info('Cleaning registries for queue: %s', queue.name) clean_registries(queue) self.last_cleaned_at = utcnow() @@ -952,7 +952,7 @@ class HerokuWorker(Worker): def handle_warm_shutdown_request(self): """If horse is alive send it SIGRTMIN""" if self.horse_pid != 0: - self.log.warning('Warm shut down requested, sending horse SIGRTMIN signal') + self.log.info('Warm shut down requested, sending horse SIGRTMIN signal') self.kill_horse(sig=signal.SIGRTMIN) else: self.log.warning('Warm shut down requested, no horse found') diff --git a/tests/test_worker.py b/tests/test_worker.py index b826f2b..acd3ffa 100644 --- a/tests/test_worker.py +++ b/tests/test_worker.py @@ -800,8 +800,8 @@ class TestWorker(RQTestCase): w = Worker([q]) job = q.enqueue(say_hello, args=('Frank',), result_ttl=10) w.perform_job(job, q) - mock_logger_info.assert_called_with('Result is kept for 10 seconds') - self.assertIn('Result is kept for 10 seconds', [c[0][0] for c in mock_logger_info.call_args_list]) + mock_logger_info.assert_called_with('Result is kept for %s seconds', 10) + self.assertIn('Result is kept for %s seconds', [c[0][0] for c in mock_logger_info.call_args_list]) @mock.patch('rq.worker.logger.info') def test_log_result_lifespan_false(self, mock_logger_info): @@ -823,7 +823,7 @@ class TestWorker(RQTestCase): w = Worker([q]) job = q.enqueue(say_hello, args=('Frank',), result_ttl=10) w.dequeue_job_and_maintain_ttl(10) - self.assertIn("Frank", mock_logger_info.call_args[0][0]) + self.assertIn("Frank", mock_logger_info.call_args[0][2]) @mock.patch('rq.worker.logger.info') def test_log_job_description_false(self, mock_logger_info): @@ -832,7 +832,7 @@ class TestWorker(RQTestCase): w = Worker([q], log_job_description=False) job = q.enqueue(say_hello, args=('Frank',), result_ttl=10) w.dequeue_job_and_maintain_ttl(10) - self.assertNotIn("Frank", mock_logger_info.call_args[0][0]) + self.assertNotIn("Frank", mock_logger_info.call_args[0][2]) def kill_worker(pid, double_kill):