classification
Title: Provide a way for assertLogs to optionally not hide the logging output
Type: enhancement Stage:
Components: Library (Lib) Versions: Python 3.6
process
Status: open Resolution:
Dependencies: Superseder:
Assigned To: Nosy List: ezio.melotti, michael.foord, r.david.murray, rbcollins, zach.ware
Priority: normal Keywords:

Created on 2015-06-01 19:15 by r.david.murray, last changed 2015-08-21 14:38 by r.david.murray.

Messages (3)
msg244608 - (view) Author: R. David Murray (r.david.murray) * (Python committer) Date: 2015-06-01 19:15
In my test framework I have a 'verbose' flag that causes the logging output to be written to the console[*], which helps greatly during debugging.  However, if assertLogs is used, the logging is suppressed, and when debugging logging failures it is really helpful to see the full logging output :).

Ideally there would be a unittest-supported 'verbose' flag that assertLogs could look at and not suppress existing logging when it is at level 2 or greater.  Or perhaps a flag specific to logging output would be better?  I don't really care what the API is as long as I can arrange to set it from the CLI as part of running individual tests.
msg248931 - (view) Author: Robert Collins (rbcollins) * (Python committer) Date: 2015-08-21 00:23
Ok so, design thoughts here.

assertLogs really does two things. Firstly it takes a copy of the logs so it can do its assertion.

Secondly it disables all other logging, cleaning up noisy tests.

Your specific need only conflicts with the second case.

The way I handle this in 'fixtures' is to automatically attach the logs to the test output, which means failures show the logs. (Successes have them too, but they are not shown by default).

Ignoring the mismatch between stock unittest and fixtures supporting unittests, does this sound like it would meet your needs? e.g. you'd use your global to make attachments be shown on success as well as failure, and then you'd have nearly identical behaviour. But not exactly:  it would still disable the during-execution output (which makes parallel and CI runs a lot nicer - the report at the end is the key).
msg248955 - (view) Author: R. David Murray (r.david.murray) * (Python committer) Date: 2015-08-21 14:38
My test harness already dumps the logging buffer on test failure.

What I need this for is debugging.  My test harness verbose = 2 flag turns on logging globally, and I need to see the logging from the code under test correctly interspersed with the other logging (some of which comes from *other processes*...there are integration tests as well as unit tests).

Here's what I'm currently using:

    @contextmanager
    def assertLogs(self, logger=None, level=None):
        cm = super().assertLogs(logger, level)
        watcher = cm.__enter__()
        if verbose > 1:
            capture_handler = cm.logger.handlers
            cm.logger.propagate = cm.old_propagate
            cm.logger.handlers = cm.old_handlers + cm.logger.handlers
        try:
            yield watcher
        finally:
            if verbose > 1:
                # Restore before exit to avoid a race.  Otherwise debug output
                # sometimes gets written to the console during non-v.
                cm.logger.propagate = False
                cm.logger.handlers = capture_handler
            cm.__exit__(None, None, None)

So, I have a solution, and if my use case is too specialized I can just continue to use that solution, though I am forced to poke at the internals to make it work :)

I am also, by the way, depending on the fact that when the logging is being done by another thread I can "watch" cm.output until specific logging that I am expecting appears in the buffer.  I'm sure that's going to make some people throw up their hands in disgust, considering among other things the fact that it involves a busy-wait, but while it may be a somewhat ugly hack, it is a hack that works well.
History
Date User Action Args
2015-08-21 14:38:32r.david.murraysetmessages: + msg248955
2015-08-21 00:23:36rbcollinssetmessages: + msg248931
2015-06-05 03:58:56zach.waresetnosy: + zach.ware
2015-06-02 19:23:55ned.deilysetnosy: + rbcollins, ezio.melotti, michael.foord
2015-06-01 19:15:30r.david.murraycreate