PyDev Unittesting: Wie man Text, der in einem logging.Logger protokolliert wird, in "Captured Output" erfasst

Question

Ich verwende PyDev für die Entwicklung und das Unit-Testing meiner Python-Anwendung. Was das Unit-Testing betrifft, so funktioniert alles prima, außer der Tatsache, dass kein Inhalt im Logging-Framework protokolliert wird. Der Logger wird nicht von der "Captured output" von PyDev erfasst.

Ich leite bereits alles, was protokolliert wird, auf diese Weise an die Standardausgabe weiter:

import sys
logger = logging.getLogger()
logger.level = logging.DEBUG
logger.addHandler(logging.StreamHandler(sys.stdout))

Dennoch zeigt die "Erfasste Ausgabe" nicht an, was in den Loggern protokolliert wird.

Hier ist ein Beispiel für ein Unittest-Skript: test.py

import sys
import unittest
import logging

logger = logging.getLogger()
logger.level = logging.DEBUG
logger.addHandler(logging.StreamHandler(sys.stdout))

class TestCase(unittest.TestCase):
    def testSimpleMsg(self):
        print("AA")
        logging.getLogger().info("BB")

Die Konsolenausgabe lautet:

Finding files... done.
Importing test modules ... done.

testSimpleMsg (itf.lowlevel.tests.hl7.TestCase) ... AA
2011-09-19 16:48:00,755 - root - INFO - BB
BB
ok

----------------------------------------------------------------------
Ran 1 test in 0.001s

OK

Aber die ERFASSTE LEISTUNG für den Test ist:

======================== CAPTURED OUTPUT =========================
AA

Weiß jemand, wie man alles erfassen kann, was in einer logging.Logger während der Durchführung dieses Tests?

Answer 1

Das Problem ist, dass die unittest Läufer ersetzt sys.stdout / sys.stderr bevor der Test beginnt, und die StreamHandler schreibt immer noch auf das Original sys.stdout .

Wenn Sie den 'aktuellen' sys.stdout zum Handler hinzufügen, sollte es funktionieren (siehe nachstehenden Code).

import sys
import unittest
import logging

logger = logging.getLogger()
logger.level = logging.DEBUG
stream_handler = logging.StreamHandler(sys.stdout)
logger.addHandler(stream_handler)

class TestCase(unittest.TestCase):
    def testSimpleMsg(self):
        stream_handler.stream = sys.stdout
        print("AA")
        logging.getLogger().info("BB")

Ein besserer Ansatz wäre jedoch das Hinzufügen/Entfernen des Handlers während des Tests:

import sys
import unittest
import logging

logger = logging.getLogger()
logger.level = logging.DEBUG

class TestCase(unittest.TestCase):
    def testSimpleMsg(self):
        stream_handler = logging.StreamHandler(sys.stdout)
        logger.addHandler(stream_handler)
        try:
            print("AA")
            logging.getLogger().info("BB")
        finally:
            logger.removeHandler(stream_handler)

Answer 2

Ich hatte es satt, manuell hinzuzufügen Fabio's großartiger Code für alle setUp s, also habe ich die Unterklasse unittest.TestCase mit einigen __metaclass__ ing:

class LoggedTestCase(unittest.TestCase):
    __metaclass__ = LogThisTestCase
    logger = logging.getLogger("unittestLogger")
    logger.setLevel(logging.DEBUG) # or whatever you prefer

class LogThisTestCase(type):
    def __new__(cls, name, bases, dct):
        # if the TestCase already provides setUp, wrap it
        if 'setUp' in dct:
            setUp = dct['setUp']
        else:
            setUp = lambda self: None
            print "creating setUp..."

        def wrappedSetUp(self):
            # for hdlr in self.logger.handlers:
            #    self.logger.removeHandler(hdlr)
            self.hdlr = logging.StreamHandler(sys.stdout)
            self.logger.addHandler(self.hdlr)
            setUp(self)
        dct['setUp'] = wrappedSetUp

        # same for tearDown
        if 'tearDown' in dct:
            tearDown = dct['tearDown']
        else:
            tearDown = lambda self: None

        def wrappedTearDown(self):
            tearDown(self)
            self.logger.removeHandler(self.hdlr)
        dct['tearDown'] = wrappedTearDown

        # return the class instance with the replaced setUp/tearDown
        return type.__new__(cls, name, bases, dct)

Jetzt kann Ihr Testfall einfach erben von LoggedTestCase d.h. class TestCase(LoggedTestCase) anstelle von class TestCase(unittest.TestCase) und Sie sind fertig. Alternativ können Sie auch die __metaclass__ Zeile und definieren Sie die logger entweder im Test oder in einer leicht veränderten LogThisTestCase .

Answer 3

Einige Leute besuchen diesen Thread wahrscheinlich, um einen Weg zu finden, die während des Testens erstellten Logs an die Konsole oder an PyDev weiterzuleiten. Die obigen Antworten bieten bereits einige Lösungen.

Wenn man bestimmte Protokolle innerhalb eines aktuellen Tests erfassen möchte, habe ich festgestellt, dass seit Python 3.4, unittest.TestCase Angebote assertLogs() der einen Kontextmanager zurückgibt, der die aktuellen Protokollmeldungen erfasst. Vom Unittest-Dokumente :

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'])

Die Nachrichten werden erfasst in cm.output . Für genauere Informationen (wie Zeit, Datei, Zeilennummer usw.) cm.records enthält eine Liste von LogRecords .

All dies geht nicht direkt auf die OP ein, die mit PyDev konfrontiert ist, bietet aber eine Möglichkeit, die erstellten Nachrichten programmatisch zu untersuchen.

Für diejenigen, die sich mit pytest kann man schön formatierte Logmeldungen an die Konsole weiterleiten, indem man die --log-cli-level=LEVEL Flagge, (zum Beispiel pytest --log-cli-level=info ).

Answer 4

Ich würde vorschlagen, ein LogCapture zu verwenden und zu testen, ob Sie wirklich das protokollieren, was Sie erwarten:

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

Answer 5

Nachdem ich die Antworten in diesem und einigen anderen verwandten Threads gelesen habe (vielen Dank!), ist hier der Kontextmanager, den ich zusammengestellt habe und der die Ausgabe des Loggers aufzeichnet (falls eine gesendet wurde).

from io import StringIO
import logging
class CaptureLogger:
    """Context manager to capture `logging` streams

    Args:
        - logger: 'logging` logger object

    Results:
        The captured output is available via `self.out`

    """

    def __init__(self, logger):
        self.logger = logger
        self.io = StringIO()
        self.sh = logging.StreamHandler(self.io)
        self.out = ''

    def __enter__(self):
        self.logger.addHandler(self.sh)
        return self

    def __exit__(self, *exc):
        self.logger.removeHandler(self.sh)
        self.out = self.io.getvalue()

    def __repr__(self):
        return f"captured: {self.out}\n"

Beispiel für die Verwendung:

logger = logging.getLogger()
msg = "Testing 1, 2, 3"
with CaptureLogger(logger) as cl:
    logger.error(msg)
assert cl.out, msg+"\n"

Da der OP danach fragte, wie man es in den aufgezeichneten stdout-Stream bekommt, kann man es nach stdout in __exit__ und fügen daher eine zusätzliche Zeile wie folgt hinzu:

    def __exit__(self, *exc):
        self.logger.removeHandler(self.sh)
        self.out = self.io.getvalue()
        print(self.out)

Diese Lösung unterscheidet sich insofern, als sie die Protokollierungsausgabe sammelt und sie am Ende auf einmal ausgibt, nachdem alle normalen print() Anrufe, falls vorhanden. So kann es oder kann nicht sein, was OP ist nach, aber das funktionierte gut für meine Bedürfnisse.