Tests no longer setup logging (less noise)

celery/tests/app/test_log.py

@@ -21,6 +21,7 @@ from celery.utils.log import (
 )
 from celery.tests.case import (
     AppCase, Case, override_stdouts, wrap_logger, get_handlers,
+    restore_logging,
 )
 
 
@@ -132,14 +133,16 @@ class test_default_logger(AppCase):
         self.assertIs(logger.parent, logging.root)
 
     def test_setup_logging_subsystem_misc(self):
-        self.app.log.setup_logging_subsystem(loglevel=None)
+        with restore_logging():
+            self.app.log.setup_logging_subsystem(loglevel=None)
 
     def test_setup_logging_subsystem_misc2(self):
-        self.app.conf.CELERYD_HIJACK_ROOT_LOGGER = True
-        try:
-            self.app.log.setup_logging_subsystem()
-        finally:
-            self.app.conf.CELERYD_HIJACK_ROOT_LOGGER = False
+        with restore_logging():
+            self.app.conf.CELERYD_HIJACK_ROOT_LOGGER = True
+            try:
+                self.app.log.setup_logging_subsystem()
+            finally:
+                self.app.conf.CELERYD_HIJACK_ROOT_LOGGER = False
 
     def test_get_default_logger(self):
         self.assertTrue(self.app.log.get_default_logger())
@@ -150,16 +153,18 @@ class test_default_logger(AppCase):
         logger.handlers[:] = []
 
     def test_setup_logging_subsystem_colorize(self):
-        self.app.log.setup_logging_subsystem(colorize=None)
-        self.app.log.setup_logging_subsystem(colorize=True)
+        with restore_logging():
+            self.app.log.setup_logging_subsystem(colorize=None)
+            self.app.log.setup_logging_subsystem(colorize=True)
 
     def test_setup_logging_subsystem_no_mputil(self):
         from celery.utils import log as logtools
-        mputil, logtools.mputil = logtools.mputil, None
-        try:
-            self.app.log.setup_logging_subsystem()
-        finally:
-            logtools.mputil = mputil
+        with restore_logging():
+            mputil, logtools.mputil = logtools.mputil, None
+            try:
+                self.app.log.setup_logging_subsystem()
+            finally:
+                logtools.mputil = mputil
 
     def _assertLog(self, logger, logmsg, loglevel=logging.ERROR):
 
@@ -176,86 +181,92 @@ class test_default_logger(AppCase):
         return self.assertFalse(val, reason)
 
     def test_setup_logger(self):
-        logger = self.setup_logger(loglevel=logging.ERROR, logfile=None,
-                                   root=False, colorize=True)
-        logger.handlers = []
-        Logging._setup = False
-        logger = self.setup_logger(loglevel=logging.ERROR, logfile=None,
-                                   root=False, colorize=None)
-        self.assertIs(
-            get_handlers(logger)[0].stream, sys.__stderr__,
-            'setup_logger logs to stderr without logfile argument.',
-        )
+        with restore_logging():
+            logger = self.setup_logger(loglevel=logging.ERROR, logfile=None,
+                                       root=False, colorize=True)
+            logger.handlers = []
+            Logging._setup = False
+            logger = self.setup_logger(loglevel=logging.ERROR, logfile=None,
+                                       root=False, colorize=None)
+            self.assertIs(
+                get_handlers(logger)[0].stream, sys.__stderr__,
+                'setup_logger logs to stderr without logfile argument.',
+            )
 
     def test_setup_logger_no_handlers_stream(self):
-        l = self.get_logger()
-        l.handlers = []
+        with restore_logging():
+            l = self.get_logger()
+            l.handlers = []
 
-        with override_stdouts() as outs:
-            stdout, stderr = outs
-            l = self.setup_logger(logfile=sys.stderr, loglevel=logging.INFO,
-                                  root=False)
-            l.info('The quick brown fox...')
-            self.assertIn('The quick brown fox...', stderr.getvalue())
+            with override_stdouts() as outs:
+                stdout, stderr = outs
+                l = self.setup_logger(logfile=sys.stderr, loglevel=logging.INFO,
+                                      root=False)
+                l.info('The quick brown fox...')
+                self.assertIn('The quick brown fox...', stderr.getvalue())
 
     def test_setup_logger_no_handlers_file(self):
-        l = self.get_logger()
-        l.handlers = []
-        tempfile = mktemp(suffix='unittest', prefix='celery')
-        l = self.setup_logger(logfile=tempfile, loglevel=0, root=False)
-        self.assertIsInstance(get_handlers(l)[0],
-                              logging.FileHandler)
+        with restore_logging():
+            l = self.get_logger()
+            l.handlers = []
+            tempfile = mktemp(suffix='unittest', prefix='celery')
+            l = self.setup_logger(logfile=tempfile, loglevel=0, root=False)
+            self.assertIsInstance(get_handlers(l)[0],
+                                  logging.FileHandler)
 
     def test_redirect_stdouts(self):
-        logger = self.setup_logger(loglevel=logging.ERROR, logfile=None,
-                                   root=False)
-        try:
-            with wrap_logger(logger) as sio:
-                self.app.log.redirect_stdouts_to_logger(
-                    logger, loglevel=logging.ERROR,
-                )
-                logger.error('foo')
-                self.assertIn('foo', sio.getvalue())
-                self.app.log.redirect_stdouts_to_logger(
-                    logger, stdout=False, stderr=False,
-                )
-        finally:
-            sys.stdout, sys.stderr = sys.__stdout__, sys.__stderr__
+        with restore_logging():
+            logger = self.setup_logger(loglevel=logging.ERROR, logfile=None,
+                                       root=False)
+            try:
+                with wrap_logger(logger) as sio:
+                    self.app.log.redirect_stdouts_to_logger(
+                        logger, loglevel=logging.ERROR,
+                    )
+                    logger.error('foo')
+                    self.assertIn('foo', sio.getvalue())
+                    self.app.log.redirect_stdouts_to_logger(
+                        logger, stdout=False, stderr=False,
+                    )
+            finally:
+                sys.stdout, sys.stderr = sys.__stdout__, sys.__stderr__
 
     def test_logging_proxy(self):
-        logger = self.setup_logger(loglevel=logging.ERROR, logfile=None,
-                                   root=False)
+        with restore_logging():
+            logger = self.setup_logger(loglevel=logging.ERROR, logfile=None,
+                                       root=False)
 
-        with wrap_logger(logger) as sio:
-            p = LoggingProxy(logger, loglevel=logging.ERROR)
-            p.close()
-            p.write('foo')
-            self.assertNotIn('foo', sio.getvalue())
-            p.closed = False
-            p.write('foo')
-            self.assertIn('foo', sio.getvalue())
-            lines = ['baz', 'xuzzy']
-            p.writelines(lines)
-            for line in lines:
-                self.assertIn(line, sio.getvalue())
-            p.flush()
-            p.close()
-            self.assertFalse(p.isatty())
-
-            with override_stdouts() as (stdout, stderr):
-                with in_sighandler():
-                    p.write('foo')
-                    self.assertTrue(stderr.getvalue())
+            with wrap_logger(logger) as sio:
+                p = LoggingProxy(logger, loglevel=logging.ERROR)
+                p.close()
+                p.write('foo')
+                self.assertNotIn('foo', sio.getvalue())
+                p.closed = False
+                p.write('foo')
+                self.assertIn('foo', sio.getvalue())
+                lines = ['baz', 'xuzzy']
+                p.writelines(lines)
+                for line in lines:
+                    self.assertIn(line, sio.getvalue())
+                p.flush()
+                p.close()
+                self.assertFalse(p.isatty())
+
+                with override_stdouts() as (stdout, stderr):
+                    with in_sighandler():
+                        p.write('foo')
+                        self.assertTrue(stderr.getvalue())
 
     def test_logging_proxy_recurse_protection(self):
-        logger = self.setup_logger(loglevel=logging.ERROR, logfile=None,
-                                   root=False)
-        p = LoggingProxy(logger, loglevel=logging.ERROR)
-        p._thread.recurse_protection = True
-        try:
-            self.assertIsNone(p.write('FOOFO'))
-        finally:
-            p._thread.recurse_protection = False
+        with restore_logging():
+            logger = self.setup_logger(loglevel=logging.ERROR, logfile=None,
+                                       root=False)
+            p = LoggingProxy(logger, loglevel=logging.ERROR)
+            p._thread.recurse_protection = True
+            try:
+                self.assertIsNone(p.write('FOOFO'))
+            finally:
+                p._thread.recurse_protection = False
 
 
 class test_task_logger(test_default_logger):

celery/tests/bin/test_beat.py

@@ -13,7 +13,7 @@ from celery import platforms
 from celery.bin import beat as beat_bin
 from celery.apps import beat as beatapp
 
-from celery.tests.case import AppCase, Mock
+from celery.tests.case import AppCase, Mock, restore_logging
 
 
 class MockedShelveModule(object):
@@ -118,24 +118,26 @@ class test_Beat(AppCase):
         MockService.in_sync = False
 
     def test_setup_logging(self):
-        try:
-            # py3k
-            delattr(sys.stdout, 'logger')
-        except AttributeError:
-            pass
-        b = beatapp.Beat(app=self.app)
-        b.redirect_stdouts = False
-        b.app.log.__class__._setup = False
-        b.setup_logging()
-        with self.assertRaises(AttributeError):
-            sys.stdout.logger
+        with restore_logging():
+            try:
+                # py3k
+                delattr(sys.stdout, 'logger')
+            except AttributeError:
+                pass
+            b = beatapp.Beat(app=self.app)
+            b.redirect_stdouts = False
+            b.app.log.__class__._setup = False
+            b.setup_logging()
+            with self.assertRaises(AttributeError):
+                sys.stdout.logger
 
     @redirect_stdouts
     @patch('celery.apps.beat.logger')
     def test_logs_errors(self, logger, stdout, stderr):
-        b = MockBeat3(app=self.app, socket_timeout=None)
-        b.start_scheduler()
-        self.assertTrue(logger.critical.called)
+        with restore_logging():
+            b = MockBeat3(app=self.app, socket_timeout=None)
+            b.start_scheduler()
+            self.assertTrue(logger.critical.called)
 
     @redirect_stdouts
     @patch('celery.platforms.create_pidlock')

celery/tests/case.py

@@ -204,12 +204,22 @@ class AppCase(Case):
             if isinstance(app.backend.client, DummyClient):
                 app.backend.client.cache.clear()
         app.backend._cache.clear()
+        root = logging.getLogger()
+        self.__rootlevel = root.level
+        self.__roothandlers = root.handlers
         self.setup()
 
     def tearDown(self):
         self.teardown()
         self._current_app.set_current()
 
+        root = logging.getLogger()
+        this = '.'.join([self.__class__.__name__, self._testMethodName])
+        if root.level != self.__rootlevel:
+            raise RuntimeError('Test {0} changed root loglevel'.format(this))
+        if root.handlers != self.__roothandlers:
+            raise RuntimeError('Test {0} changed root handlers'.format(this))
+
     def setup(self):
         pass
 
@@ -609,3 +619,16 @@ def body_from_sig(app, sig, utc=True):
         'utc': utc,
         'expires': expires,
     }
+
+
+@contextmanager
+def restore_logging():
+    root = logging.getLogger()
+    level = root.level
+    handlers = root.handlers
+
+    try:
+        yield
+    finally:
+        root.level = level
+        root.handlers[:] = handlers

celery/tests/events/test_snapshot.py

@@ -4,7 +4,7 @@ from mock import patch
 
 from celery.events import Events
 from celery.events.snapshot import Polaroid, evcam
-from celery.tests.case import AppCase
+from celery.tests.case import AppCase, restore_logging
 
 
 class TRef(object):
@@ -119,14 +119,15 @@ class test_evcam(AppCase):
         self.app.events = self.prev
 
     def test_evcam(self):
-        evcam(Polaroid, timer=timer)
-        evcam(Polaroid, timer=timer, loglevel='CRITICAL')
-        self.MockReceiver.raise_keyboard_interrupt = True
-        try:
-            with self.assertRaises(SystemExit):
-                evcam(Polaroid, timer=timer)
-        finally:
-            self.MockReceiver.raise_keyboard_interrupt = False
+        with restore_logging():
+            evcam(Polaroid, timer=timer)
+            evcam(Polaroid, timer=timer, loglevel='CRITICAL')
+            self.MockReceiver.raise_keyboard_interrupt = True
+            try:
+                with self.assertRaises(SystemExit):
+                    evcam(Polaroid, timer=timer)
+            finally:
+                self.MockReceiver.raise_keyboard_interrupt = False
 
     @patch('celery.platforms.create_pidlock')
     def test_evcam_pidfile(self, create_pidlock):

celery/tests/worker/test_worker.py

@@ -32,7 +32,7 @@ from celery.utils import worker_direct
 from celery.utils.serialization import pickle
 from celery.utils.timer2 import Timer
 
-from celery.tests.case import AppCase, Case
+from celery.tests.case import AppCase, Case, restore_logging
 
 
 def MockStep(step=None):
@@ -878,40 +878,41 @@ class test_WorkController(AppCase):
     @patch('celery.platforms.signals')
     @patch('celery.platforms.set_mp_process_title')
     def test_process_initializer(self, set_mp_process_title, _signals):
-        from celery import Celery
-        from celery import signals
-        from celery._state import _tls
-        from celery.concurrency.processes import process_initializer
-        from celery.concurrency.processes import (WORKER_SIGRESET,
-                                                  WORKER_SIGIGNORE)
-
-        def on_worker_process_init(**kwargs):
-            on_worker_process_init.called = True
-        on_worker_process_init.called = False
-        signals.worker_process_init.connect(on_worker_process_init)
-
-        loader = Mock()
-        loader.override_backends = {}
-        app = Celery(loader=loader, set_as_current=False)
-        app.loader = loader
-        app.conf = AttributeDict(DEFAULTS)
-        process_initializer(app, 'awesome.worker.com')
-        _signals.ignore.assert_any_call(*WORKER_SIGIGNORE)
-        _signals.reset.assert_any_call(*WORKER_SIGRESET)
-        self.assertTrue(app.loader.init_worker.call_count)
-        self.assertTrue(on_worker_process_init.called)
-        self.assertIs(_tls.current_app, app)
-        set_mp_process_title.assert_called_with(
-            'celeryd', hostname='awesome.worker.com',
-        )
+        with restore_logging():
+            from celery import Celery
+            from celery import signals
+            from celery._state import _tls
+            from celery.concurrency.processes import process_initializer
+            from celery.concurrency.processes import (WORKER_SIGRESET,
+                                                    WORKER_SIGIGNORE)
+
+            def on_worker_process_init(**kwargs):
+                on_worker_process_init.called = True
+            on_worker_process_init.called = False
+            signals.worker_process_init.connect(on_worker_process_init)
+
+            loader = Mock()
+            loader.override_backends = {}
+            app = Celery(loader=loader, set_as_current=False)
+            app.loader = loader
+            app.conf = AttributeDict(DEFAULTS)
+            process_initializer(app, 'awesome.worker.com')
+            _signals.ignore.assert_any_call(*WORKER_SIGIGNORE)
+            _signals.reset.assert_any_call(*WORKER_SIGRESET)
+            self.assertTrue(app.loader.init_worker.call_count)
+            self.assertTrue(on_worker_process_init.called)
+            self.assertIs(_tls.current_app, app)
+            set_mp_process_title.assert_called_with(
+                'celeryd', hostname='awesome.worker.com',
+            )
 
-        with patch('celery.app.trace.setup_worker_optimizations') as swo:
-            os.environ['FORKED_BY_MULTIPROCESSING'] = "1"
-            try:
-                process_initializer(app, 'luke.worker.com')
-                swo.assert_called_with(app)
-            finally:
-                os.environ.pop('FORKED_BY_MULTIPROCESSING', None)
+            with patch('celery.app.trace.setup_worker_optimizations') as swo:
+                os.environ['FORKED_BY_MULTIPROCESSING'] = "1"
+                try:
+                    process_initializer(app, 'luke.worker.com')
+                    swo.assert_called_with(app)
+                finally:
+                    os.environ.pop('FORKED_BY_MULTIPROCESSING', None)
 
     def test_attrs(self):
         worker = self.worker