Wie soll ich eine Protokollmeldung überprüfen, wenn ich Python-Code unter der Nase teste?

78

Ich versuche, einen einfachen Komponententest zu schreiben, der überprüft, ob eine Klasse in meiner Anwendung unter bestimmten Bedingungen einen Fehler über die Standardprotokollierungs-API protokolliert. Ich kann nicht herausfinden, wie diese Situation am saubersten getestet werden kann.

Ich weiß, dass die Nase die Protokollausgabe bereits über das Protokollierungs-Plugin erfasst, aber dies scheint als Berichts- und Debugging-Hilfe für fehlgeschlagene Tests gedacht zu sein.

Die zwei Möglichkeiten, dies zu tun, sind:

  • Verspotten Sie das Protokollierungsmodul entweder stückweise (mymodule.logging = mockloggingmodule) oder mit einer geeigneten Verspottungsbibliothek.
  • Schreiben oder verwenden Sie ein vorhandenes Nasen-Plugin, um die Ausgabe zu erfassen und zu überprüfen.

Wenn ich mich für den früheren Ansatz entscheide, würde ich gerne wissen, wie ich den globalen Status am saubersten auf den ursprünglichen Stand zurücksetzen kann, bevor ich das Protokollierungsmodul verspottet habe.

Ich freue mich auf Ihre Tipps und Tricks zu diesem Thema ...

jkp
quelle
2
Es gibt jetzt eine eingebaute Möglichkeit, dies zu tun: docs.python.org/3/library/…
wkschwartz

Antworten:

23

Früher habe ich Logger verspottet, aber in dieser Situation fand ich es am besten, Logging-Handler zu verwenden. Deshalb habe ich diesen auf der Grundlage des von jkp vorgeschlagenen Dokuments geschrieben (jetzt tot, aber im Internetarchiv zwischengespeichert ).

class MockLoggingHandler(logging.Handler):
    """Mock logging handler to check for expected logs."""

    def __init__(self, *args, **kwargs):
        self.reset()
        logging.Handler.__init__(self, *args, **kwargs)

    def emit(self, record):
        self.messages[record.levelname.lower()].append(record.getMessage())

    def reset(self):
        self.messages = {
            'debug': [],
            'info': [],
            'warning': [],
            'error': [],
            'critical': [],
        }
Gus
quelle
1
Der obige Link ist tot und ich habe mich gefragt, ob jemand etwas über die Verwendung dieses Codes posten könnte. Wenn ich versuche, diesen Protokollierungshandler hinzuzufügen, wird immer wieder der Fehler angezeigt, wenn ich versuche, ihn als zu verwenden AttributeError: class MockLoggingHandler has no attribute 'level'.
Randy
127

Ab Python 3.4 bietet die Standard- Unittest- Bibliothek einen neuen Test Assertion Context Manager assertLogs. Aus den Dokumenten :

with self.assertLogs('foo', level='INFO') as cm:
    logging.getLogger('foo').info('first message')
    logging.getLogger('foo.bar').error('second message')
    self.assertEqual(cm.output, ['INFO:foo:first message',
                                 'ERROR:foo.bar:second message'])
el.atomo
quelle
38

Glücklicherweise müssen Sie dies nicht selbst schreiben. Das testfixturesPaket bietet einen Kontextmanager, der alle Protokollierungsausgaben erfasst, die im Hauptteil der withAnweisung auftreten. Das Paket finden Sie hier:

http://pypi.python.org/pypi/testfixtures

Und hier sind die Dokumente zum Testen der Protokollierung:

http://testfixtures.readthedocs.org/en/latest/logging.html

Brandon Rhodes
quelle
2
Diese Lösung sah nicht nur eleganter aus, sondern funktionierte auch für mich, während die anderen dies nicht taten (mein Protokoll stammt aus mehreren Threads).
Paulo SantAnna
33

UPDATE : Die unten stehende Antwort ist nicht mehr erforderlich. Verwenden Sie stattdessen die integrierte Python-Methode !

Diese Antwort erweitert die Arbeit unter https://stackoverflow.com/a/1049375/1286628 . Der Handler ist weitgehend derselbe (der Konstruktor ist idiomatischer super). Außerdem füge ich eine Demonstration hinzu, wie der Handler mit den Standardbibliotheken verwendet wird unittest.

class MockLoggingHandler(logging.Handler):
    """Mock logging handler to check for expected logs.

    Messages are available from an instance's ``messages`` dict, in order, indexed by
    a lowercase log level string (e.g., 'debug', 'info', etc.).
    """

    def __init__(self, *args, **kwargs):
        self.messages = {'debug': [], 'info': [], 'warning': [], 'error': [],
                         'critical': []}
        super(MockLoggingHandler, self).__init__(*args, **kwargs)

    def emit(self, record):
        "Store a message from ``record`` in the instance's ``messages`` dict."
        try:
            self.messages[record.levelname.lower()].append(record.getMessage())
        except Exception:
            self.handleError(record)

    def reset(self):
        self.acquire()
        try:
            for message_list in self.messages.values():
                message_list.clear()
        finally:
            self.release()

Dann können Sie den Handler in einer Standardbibliothek unittest.TestCasewie folgt verwenden:

import unittest
import logging
import foo

class TestFoo(unittest.TestCase):

    @classmethod
    def setUpClass(cls):
        super(TestFoo, cls).setUpClass()
        # Assuming you follow Python's logging module's documentation's
        # recommendation about naming your module's logs after the module's
        # __name__,the following getLogger call should fetch the same logger
        # you use in the foo module
        foo_log = logging.getLogger(foo.__name__)
        cls._foo_log_handler = MockLoggingHandler(level='DEBUG')
        foo_log.addHandler(cls._foo_log_handler)
        cls.foo_log_messages = cls._foo_log_handler.messages

    def setUp(self):
        super(TestFoo, self).setUp()
        self._foo_log_handler.reset() # So each test is independent

    def test_foo_objects_fromble_nicely(self):
        # Do a bunch of frombling with foo objects
        # Now check that they've logged 5 frombling messages at the INFO level
        self.assertEqual(len(self.foo_log_messages['info']), 5)
        for info_message in self.foo_log_messages['info']:
            self.assertIn('fromble', info_message)
wkschwartz
quelle
Vielen Dank, dass Sie erklärt haben, wie Sie die Antwort von Gustavo verwenden und erweitern können.
Harshdeep
2
Es gibt jetzt eine eingebaute Möglichkeit, dies zu tun: docs.python.org/3/library/…
wkschwartz
1
In setUpClass hat der Aufruf von foo_log.addHandler () einen fehlenden Unterstrich vor der foo_log_handlerVariablen
PaulR
Dies ist immer noch nützlich für Python 2.x.
JDhildeb
1
Vermutlich wurde jeder in Python 2 geschriebene Code, der noch verwendet wird, bereits getestet. Wenn Sie sich in der Testschreibphase eines Projekts befinden, ist es wahrscheinlich besser, jetzt einfach zu Python 3 zu wechseln. Python 2 wird in ungefähr anderthalb Jahren die Unterstützung (einschließlich Sicherheitsupdates) verlieren.
wkschwartz
12

Brandons Antwort:

pip install testfixtures

Ausschnitt:

import logging
from testfixtures import LogCapture
logger = logging.getLogger('')


with LogCapture() as logs:
    # my awesome code
    logger.error('My code logged an error')
assert 'My code logged an error' in str(logs)

Hinweis: Das oben Gesagte steht nicht im Widerspruch zum Aufrufen von Nosetests und zum Abrufen der Ausgabe des logCapture-Plugins des Tools

Yauhen Yakimovich
quelle
3

Als Folge von Reefs Antwort habe ich mir erlaubt , ein Beispiel mit Pymox zu codieren . Es werden einige zusätzliche Hilfsfunktionen eingeführt, die das Stub von Funktionen und Methoden erleichtern.

import logging

# Code under test:

class Server(object):
    def __init__(self):
        self._payload_count = 0
    def do_costly_work(self, payload):
        # resource intensive logic elided...
        pass
    def process(self, payload):
        self.do_costly_work(payload)
        self._payload_count += 1
        logging.info("processed payload: %s", payload)
        logging.debug("payloads served: %d", self._payload_count)

# Here are some helper functions
# that are useful if you do a lot
# of pymox-y work.

import mox
import inspect
import contextlib
import unittest

def stub_all(self, *targets):
    for target in targets:
        if inspect.isfunction(target):
            module = inspect.getmodule(target)
            self.StubOutWithMock(module, target.__name__)
        elif inspect.ismethod(target):
            self.StubOutWithMock(target.im_self or target.im_class, target.__name__)
        else:
            raise NotImplementedError("I don't know how to stub %s" % repr(target))
# Monkey-patch Mox class with our helper 'StubAll' method.
# Yucky pymox naming convention observed.
setattr(mox.Mox, 'StubAll', stub_all)

@contextlib.contextmanager
def mocking():
    mocks = mox.Mox()
    try:
        yield mocks
    finally:
        mocks.UnsetStubs() # Important!
    mocks.VerifyAll()

# The test case example:

class ServerTests(unittest.TestCase):
    def test_logging(self):
        s = Server()
        with mocking() as m:
            m.StubAll(s.do_costly_work, logging.info, logging.debug)
            # expectations
            s.do_costly_work(mox.IgnoreArg()) # don't care, we test logging here.
            logging.info("processed payload: %s", 'hello')
            logging.debug("payloads served: %d", 1)
            # verified execution
            m.ReplayAll()
            s.process('hello')

if __name__ == '__main__':
    unittest.main()
Pavel Repin
quelle
2
Ich mag Ihre innovative Verwendung eines Contextmanager-Dekorateurs zur Implementierung von "Scoped Mocking". Nett.
JKP
PS: Es ist eine echte Schande, dass PyMOX keine pep8-Konformität aufweist.
JKP
2

Sie sollten Mocking verwenden, da Sie eines Tages Ihren Logger möglicherweise in einen Datenbank-Logger ändern möchten. Sie werden nicht glücklich sein, wenn während Nosetests versucht wird, eine Verbindung zur Datenbank herzustellen.

Das Verspotten funktioniert auch dann weiter, wenn die Standardausgabe unterdrückt wird.

Ich habe pyMox 'Stubs verwendet. Denken Sie daran, die Stichleitungen nach dem Test zu deaktivieren.

Paweł Polewicz
quelle
+1 Einige der Vorteile von AOP. Anstatt jedes Backend in eine Klasse / ein Objekt im generischen Stil zu verpacken.
Aiden Bell
1

Wenn Sie eine Hilfsmethode wie diese definieren:

import logging

def capture_logging():
    records = []

    class CaptureHandler(logging.Handler):
        def emit(self, record):
            records.append(record)

        def __enter__(self):
            logging.getLogger().addHandler(self)
            return records

        def __exit__(self, exc_type, exc_val, exc_tb):
            logging.getLogger().removeHandler(self)

    return CaptureHandler()

Dann können Sie folgenden Testcode schreiben:

    with capture_logging() as log:
        ... # trigger some logger warnings
    assert len(log) == ...
    assert log[0].getMessage() == ...
Craig Gidney
quelle
0

Ich habe die Antwort von @ Reef eingegeben und den folgenden Code ausprobiert. Es funktioniert gut für mich sowohl für Python 2.7 (wenn Sie Mock installieren ) als auch für Python 3.4.

"""
Demo using a mock to test logging output.
"""

import logging
try:
    import unittest
except ImportError:
    import unittest2 as unittest

try:
    # Python >= 3.3
    from unittest.mock import Mock, patch
except ImportError:
    from mock import Mock, patch

logging.basicConfig()
LOG=logging.getLogger("(logger under test)")

class TestLoggingOutput(unittest.TestCase):
    """ Demo using Mock to test logging INPUT. That is, it tests what
    parameters were used to invoke the logging method, while still
    allowing actual logger to execute normally.

    """
    def test_logger_log(self):
        """Check for Logger.log call."""
        original_logger = LOG
        patched_log = patch('__main__.LOG.log',
                            side_effect=original_logger.log).start()

        log_msg = 'My log msg.'
        level = logging.ERROR
        LOG.log(level, log_msg)

        # call_args is a tuple of positional and kwargs of the last call
        # to the mocked function.
        # Also consider using call_args_list
        # See: https://docs.python.org/3/library/unittest.mock.html#unittest.mock.Mock.call_args
        expected = (level, log_msg)
        self.assertEqual(expected, patched_log.call_args[0])


if __name__ == '__main__':
    unittest.main()
Twildfarmer
quelle