Move pytest-logging functionality to pytest-catchlog. #20

s0undt3ch · 2015-11-15T13:11:59Z

Fixes #14

abusalimov · 2015-11-15T13:26:45Z

Thank you!

I think your logic could and should be more integrated into the existing code. For example, I believe, it could be achieved without attaching one more handler and formatter. How about reusing LogCaptureHandler(), which is created in _runtest_for()?

s0undt3ch · 2015-11-15T13:33:10Z

LogCaptureHandler does not write to sys.stderr if I'm reading it correctly...

abusalimov · 2015-11-15T14:17:31Z

pytest_catchlog.py

+    Class to add new hooks to pytest
+    """
+
+    def pytest_register_logging_levels(self):


Do we really need to know all user-defined levels. What's about just calculating the desired level from the verbosity flag, using a fixed formula, like level = logging.ERROR - 10*v?

I don't think you can get a fixed formula to account for user defined levels... However, it just made me realize that python logging module does know about these levels, so I'll see if there's a way to avoid the custom hook.

I don't think you can get a fixed formula to account for user defined levels...

Why not? User level are anyway somewhere between NOTSET and CRITICAL, more likely between NOTSET and DEBUG. So we could just take it into consideration, i.e. scale the range properly, for example:

ERROR (40) default WARNING (30) -v INFO (20) -vv DEBUG (10) -vvv CUSTOM (5) -vvvv CUSTOM (2) -vvvvv

Or just let the user to customize it through pytest.ini maybe...

I'd like to avoid guessing or getting close. The logging module should give use the available logging levels, though, libraries which are late imported could add log levels after the plugin has had a chance to translate verbosity to log level...

abusalimov · 2015-11-15T14:19:24Z

LogCaptureHandler does not write to sys.stderr if I'm reading it correctly...

Then we should teach it to, depending on the -s/--capture flag, I guess.

abusalimov · 2015-11-15T14:23:35Z

pytest_catchlog.py

+logging.root.addHandler(CONSOLEHANDLER)
+# The root logging should have the lowest logging level to allow all messages
+# to be "passed" to the handlers
+logging.root.setLevel(1)


This shouldn't be done at the global script level, since it effectively forbids the module to be imported by anyone, including various tools.

s0undt3ch · 2015-11-15T14:42:34Z

Hmm... I'll move it...
Is there a way to tell pytest to configure this plugin before others? Even on a best effort?
We want logging setup as early as possible...

abusalimov · 2015-11-15T14:50:26Z

Is there a way to tell pytest to configure this plugin before others? Even on a best effort?

You could use @pytest.mark.tryfirst for that.

s0undt3ch · 2015-11-16T12:28:24Z

LogCaptureHandler does not write to sys.stderr if I'm reading it correctly...

Then we should teach it to, depending on the -s/--capture flag, I guess.

Here's my issue with LogCaptureHandler, if I read the code correctly, a new handler is instantiated before each test is executed, my purpose with pytest-logging was to even provide logging for any other py.test plugins which needed it, not just while running a test.

abusalimov · 2015-11-16T12:39:19Z

if I read the code correctly, a new handler is instantiated before each test is executed, my purpose with pytest-logging was to even provide logging for any other py.test plugins which needed it, not just while running a test

You're right, but I'm not sure that that behavior is desired for most users. Honestly, I can't imagine a case when I would be interested in what is happening outside my tests.

Could you provide an example, please?

@The-Compiler @eisensheng, what do you think?

s0undt3ch · 2015-11-16T12:44:22Z

As I had mentioned on the issue filed against my plugin, I am sometimes, actually quite often, interested on some boiler plate logging that happens when preparing the test suite, that's why I needed logging support in pytest in the first place...

s0undt3ch · 2015-11-16T12:46:08Z

I suggest keeping 2 handlers, which already exists, which takes care of catching the log messages, and one responsible for printing them to the console. In this case, CatchLogHandler wouldn't need to subclass stream handler since we would already have a stream handler installed...

s0undt3ch · 2015-11-16T12:47:37Z

I'm also interested on logging that happens on libraries that I use with my own library, hence me setting the root logger level to 1, so we'd get all logging from all libraries that are used by the code being tested.

abusalimov · 2015-11-16T12:52:27Z

I am sometimes, actually quite often, interested on some boiler plate logging that happens when preparing the test suite

catchlog handles this as well by setting up a handler that captures logs during setup phase, i.e. preparing and running necessary fixtures needed to run a test case. Isn't this what you need?

s0undt3ch · 2015-11-16T12:55:18Z

I'm trying to see if I can "fit" your concerns into some usable code....

abusalimov · 2015-11-16T13:01:31Z

I mean, if you just need to log some boilerplate code that fits the standard pytest fixtures concept or setup hook wrappers, then everything should work fine already.

@pytest.fixture
def fixx():
    logger.error('FIXX')

def test_foo(caplog, fixx):
    logger.info('test')

In this example, both log lines are captured, yet by handlers created separately.

s0undt3ch · 2015-11-16T13:03:37Z

Yes, I read that correctly, but I'm hacking another pytest plugin which needs logging, and I'm trying to confirm if that approach will serve that purpose as well, pytest-logging was going to facilitate logging to other plugins...

s0undt3ch · 2015-11-16T13:39:42Z

So far, hook usage was dropped...

abusalimov · 2015-11-16T13:42:53Z

I suggest keeping 2 handlers, which already exists, which takes care of catching the log messages, and one responsible for printing them to the console. In this case, CatchLogHandler wouldn't need to subclass stream handler since we would already have a stream handler installed...

On the second thought, it could be a good solution to keep a single handler instance attached to the logging subsystem (either streaming to stderr or capturing records into a buffer, depending on the cmdline options).

This reflects how the standard stdout/stderr capturing works, to some extent. Also this could reduce the overhead of configuring the logging subsystem each time a test function runs.

s0undt3ch · 2015-11-16T15:04:19Z

Well, I actually have to disagree with you... I'll explain.

When I coded pytest-logging I was looking for an easy way to get all logging, before, during and after running the test suite, for all libraries involved. This is something that is most likely to be used while developing tests or while debugging why a test started to fail, not all the time.
However, on a CI context, I'm most likely interested on the logging that happened while the test was being prep'ed till the end of it, that's why CatchLogHandler uses a TextIO stream(to get back the stream contents and include them in the report).
The console stream is "attached" to sys.stderr, you can't get back it's contents.

So either e attach 2 stream to CatchLogHandler(in case verbosity is higher than 1) and write to both streams, or, we have separate handlers(which actually serve 2 different purposes....)

abusalimov · 2015-11-16T16:12:44Z

You seem to miss the point, I was talking on. I can understand both use-cases you described, and that's exactly what I meant by saying

either streaming to stderr or capturing records into a buffer, depending on the cmdline options

What I'm also trying to say is that you won't need both handlers at once. But I was not suggesting to merge the logic providing these two distinct flavors into a single Handler class. There likely should be two classes, though only one of them is instantiated and attached as a logging handler.

s0undt3ch · 2015-11-16T16:53:54Z

Ok, please review the code again. No hook usage(although that breaks pypy testing so I'm skipping those), and no global instantiation...
Still 2 separate stream handlers.

Let me know if this is more likely to get merged of if there's still something else that I need to address...

s0undt3ch · 2015-11-16T16:54:59Z

Honestly, I'd prefer to support the hooks as it previously did, but i's your call now...

s0undt3ch · 2015-11-16T16:58:36Z

Then its the or that I'm missing. There might be tests which will need
the captured log, so, I believe it shouldn't be a matter of or. You'll
get 2 handler, one which has the ability to output to the console in
realtime(which can't be used in tests to confirm that a log message was
issued), the other which store the log messages and is capable of allowing
a test to ensure that a log message was issued....

On 16 November 2015 at 16:12, Eldar Abusalimov [email protected]
wrote:

You seem to miss the point, I was talking on. I can understand both
use-cases you described, and that's exactly what I meant by saying

either streaming to stderr or capturing records into a buffer, depending
on the cmdline options

What I'm also trying to say is that you won't need both handlers at once.
But I was not suggesting to merge the logic providing these two distinct
flavors into a single Handler class. There likely should be two classes,
though only one of them is instantiated and attached as a logging handler.

—
Reply to this email directly or view it on GitHub
#20 (comment)
.

Pedro Algarvio

abusalimov · 2015-11-16T17:09:29Z

(which can't be used in tests to confirm that a log message was
issued), the other which store the log messages and is capable of allowing
a test to ensure that a log message was issued....

Yeah, its true. I meant only the part responsible for reporting logs in case of a failure, not caplog fixture stuff.

I have pushed some experimental changes that I made two month ago as part of #7. They include separating Handlers responsible for reporting and inspecting. I should have given you that links first, that would probably clarify a lot: 00b394d and 12e7ce0.

s0undt3ch · 2015-11-17T14:02:09Z

Let me know if there's anything else that you want me to address differently.
Also, I'd like to include back the hooks since a library which adds log levels might be late imported and catchlog won't have access to those newly added log levels. Are you completely against?

abusalimov · 2015-11-19T16:32:14Z

pytest_catchlog.py

+        logging.root.addHandler(self.console)
+        # The root logging should have the lowest logging level to allow all
+        # messages to be "passed" to the handlers
+        logging.root.setLevel(1)


AFAIK, the lowest level is 0, i.e. logging.NOTSET.

abusalimov · 2015-11-19T16:59:15Z

@s0undt3ch Sorry for the delayed response.

Also, I'd like to include back the hooks since a library which adds log levels might be late imported and catchlog won't have access to those newly added log levels. Are you completely against?

Honestly I don't like the hooks approach. But I have some thoughts about a similar ini-option:

[pytest]
log_level_extra = 
    TRACE           # infer proper number of -v from the level value
    -vvvv:GARBAGE   # or map the verbosity flag explicitly

What do you think?

abusalimov · 2015-12-10T22:51:56Z

You're very welcome, thank you for the efforts!

s0undt3ch · 2015-12-11T14:44:34Z

I've updated the PR with your suggestions. I did however left some of the logic in a more verbose and commented way to better enlighten someone who's reading that for the first time. If you prefer, I'll shorten that too.

abusalimov · 2015-12-11T22:15:07Z

pytest_catchlog.py

+        #                               log messages are displayd)
+        # verbosity=1   -v    CRITICAL (pytest verbosity kicks in, but only
+        #                               log messages with higher or equal
+        #                               level to CRITICAL are shown)


Wait, but FATAL is just an alias for CRITICAL...

Err... Then that I didn't include it in the first implementation.... Thanks. I'll fix.

But why is the highest level not included at the first place? It would eliminate the need to start counting from 1 in the enumerate call below, and let us use zero-based indices I was talking about yesterday...

s0undt3ch · 2015-12-11T22:47:34Z

Updated.

abusalimov · 2015-12-11T22:53:27Z

Hi,

Could you join our gitter chat now? I have some though I'd like to discuss
with you.

Regards,
Eldar
On Dec 12, 2015 1:47 AM, "Pedro Algarvio" [email protected] wrote:

Updated.

—
Reply to this email directly or view it on GitHub
#20 (comment)
.

abusalimov · 2015-12-12T12:02:05Z

pytest_catchlog.py



 def pytest_configure(config):
    """Always register the log catcher plugin with py.test or tests can't
    find the  fixture function.
    """
+    verbosity = config.getoption('-v')
+    if verbosity < 1:
+        cli_handler_level = logging.FATAL


I guess logging.CRITICAL is preferred over it's alias. The official docs used to use CRITICAL.

abusalimov · 2015-12-12T13:10:31Z

What do think about moving the level range checking logic into the first loop, which parses ini-option?

def pytest_configure(config):
    available_levels = set([
        logging.NOTSET,
        logging.DEBUG,
        logging.INFO,
        logging.WARNING,
        logging.ERROR,
        logging.CRITICAL,
    ])
    for level in get_option_ini(config, 'log_extra_levels'):
        try:
            level_num = int(getattr(logging, level, level))
        except ValueError:
            raise pytest.UsageError('...')
        else:
            if not (logging.NOTSET <= level_num <= logging.CRITICAL):
                config.warn("'{0}' is ignored as not being in the valid range")
                continue

        available_levels.add(level_num)

    log_levels = sorted(available_levels)

After that, adjusting the level based on the verbosity becomes extremely simple and straightforward:

    base_idx = log_levels.index(logging.WARNING)  # This is the default level.
    verbosity = config.getoption('-v')

    level_idx = base_idx - verbosity  # also need to clip it into a valid range

    cli_handler_level = log_levels[level_idx]

And here's how I would do the range clipping (any of these):

Using a separate function suggested above:

level_idx = clamp(base_idx - verbosity, 0, len(log_levels)-1)

OR using a one-liner:

level_idx = min(max(base_idx - verbosity, 0), len(log_levels)-1)

OR the same thing, but in three lines:

level_idx = base_idx - verbosity
level_idx = max(level_idx, 0)
level_idx = min(level_idx, len(log_levels)-1)

OR an imperative one:

level_idx = base_idx - verbosity
if level_idx < 0:
    level_idx = 0
elif level_idx > len(log_levels)-1:
    level_idx = -1

OR more elegant:

level_idx = base_idx - verbosity
if not (0 <= level_idx < len(log_levels)):
    level_idx = (0 if level_idx < base_idx else -1)

Personally, I like this one the most, because it clearly shows the intention just through the code itself.

OR more extremal:

level_idx = base_idx - verbosity
if not (0 <= level_idx < len(log_levels)):
    level_idx = -(level_idx > base_idx)  # 0 or -1

s0undt3ch · 2015-12-12T13:10:41Z

CRITICAL is now included and the logic is zero index based.

s0undt3ch · 2015-12-12T14:09:42Z

Updated(without the clamping logic), see if you still prefer it in another way.

abusalimov · 2015-12-12T18:30:08Z

pytest_catchlog.py

+                        level,
+                        logging.NOTSET,
+                        logging.CRITICAL))
+                continue


Excess (raise above)

Don't follow the excess part, its still a usage error and your config.warn suggestion seemed too shy and easy to miss. You'd need to pass -rw to see it right?

And, we should stick with the same error reporting for both situations. So either the usage error, or the warn. Unless I'm missing something, which is also possible.

So, which one?

No, I just meant that continue after raise is never reached anyway.

Oh. Oops. Yeah, absolutely right.

And, we should stick with the same error reporting for both situations. So either the usage error, or the warn.

Makes sense to me. I agree with your choice.

s0undt3ch · 2015-12-12T19:09:47Z

Updated.

abusalimov · 2015-12-13T18:03:17Z

Let's summarize remaining issues:

The default level is logging.CRITICAL, and basically only -v (i.e. non-negative verbosity) has an effect (should also handle -q). Possible solutions are proposed above
Verbosity only affects the level of live logs. It is unclear whether we also need to adjust the capturing level
When live logs are not enabled (the default behavior when no args are passed), logs are captured both as usual and also through the stderr, i.e. duplicated. Dedicated caplog recording handler #24 and Live logs (-s / --capture=no) #25 fix this
(feature) Setting the log level explicitly through --log-level (overrides -vvv)
README

I think most of these (maybe except the README) can and should be addressed separately, after merging this PR.

@s0undt3ch The one last thing I would ask you for is to squash the whole changeset into a single commit, or few commits like feature+tests+readme, as you wish.

I'd also like to hear final comments from @eisensheng and @The-Compiler on this epic PR.

The-Compiler · 2015-12-14T08:03:47Z

pytest_catchlog.py

+    #                               higher or equal level to WARNING)
+    # verbosity=4   -vvv  INFO
+    # - ... etc
+    handled_levels = dict(enumerate(sorted(available_levels, reverse=True)))


I haven't followed the previous discussion, but intuitively to me it'd make sense to show CRITICAL and ERROR without -v (maybe even WARNING), and then have -v or -vv for INFO. Not displaying errors without -v sounds wrong, IMHO.

abusalimov · 2015-12-23T10:46:58Z

@s0undt3ch any news?

s0undt3ch · 2015-12-23T11:00:33Z

Sorry, this Xmas season is kind of busy for me. I'll try to do what you asked today or tomorrow..

abusalimov · 2015-12-23T11:10:01Z

Thanks! If you're really that busy, I could fix the remaining issues after merging into develop. I would appreciate though if you squash all commits into a single one or two.

s0undt3ch · 2015-12-23T16:56:30Z

17 months bold twins and the whole family coming over for Xmas...yeah, busy.

Anyway, squashed. If you could take a look at the remaining issues, I'd be grateful.

Thanks! And merry XMas!

abusalimov · 2015-12-26T00:28:45Z

Merry XMas!
Thank you. I'll try fix the rest in few days or a week.

Fixes #14

s0undt3ch · 2016-01-23T18:55:37Z

I found a need to log to a file all logging that is happening, at a different level that what's being shown in the console.
Should I add a commit to this pull request? Prefer it in a separate PR? part of the required functionality is already present in this PR...

abusalimov · 2016-01-23T19:49:14Z

I think, making a separate PR is a better option anyway...

s0undt3ch · 2016-01-24T14:10:19Z

So, would everyone be happy if:

we stopped relying on -v or -q and start using --log-level explicitly instead?
Default to ERROR logging level

s0undt3ch mentioned this pull request Nov 15, 2015

Rename plugin to pytest-logging #19

Closed

abusalimov reviewed Nov 15, 2015
View reviewed changes

abusalimov reviewed Nov 19, 2015
View reviewed changes

abusalimov reviewed Dec 11, 2015
View reviewed changes

abusalimov reviewed Dec 12, 2015
View reviewed changes

The-Compiler reviewed Dec 14, 2015
View reviewed changes

Move pytest-logging functionality to pytest-catchlog.

a2d6170

Fixes #14

s0undt3ch mentioned this pull request Jan 25, 2016

[Simplified] Move pytest-logging functionality to pytest-catchlog #33

Merged

s0undt3ch mentioned this pull request Jul 28, 2016

pytest -v -s script.py not showing any log vmware-archive/pytest-logging#2

Closed

eisensheng closed this in #33 Aug 7, 2016

Move pytest-logging functionality to pytest-catchlog. #20

Move pytest-logging functionality to pytest-catchlog. #20

Conversation

s0undt3ch commented Nov 15, 2015

abusalimov commented Nov 15, 2015

s0undt3ch commented Nov 15, 2015

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

abusalimov commented Nov 15, 2015

Choose a reason for hiding this comment

s0undt3ch commented Nov 15, 2015

abusalimov commented Nov 15, 2015

s0undt3ch commented Nov 16, 2015

abusalimov commented Nov 16, 2015

s0undt3ch commented Nov 16, 2015

s0undt3ch commented Nov 16, 2015

s0undt3ch commented Nov 16, 2015

abusalimov commented Nov 16, 2015

s0undt3ch commented Nov 16, 2015

abusalimov commented Nov 16, 2015

s0undt3ch commented Nov 16, 2015

s0undt3ch commented Nov 16, 2015

abusalimov commented Nov 16, 2015

s0undt3ch commented Nov 16, 2015

abusalimov commented Nov 16, 2015

s0undt3ch commented Nov 16, 2015

s0undt3ch commented Nov 16, 2015

s0undt3ch commented Nov 16, 2015

abusalimov commented Nov 16, 2015

s0undt3ch commented Nov 17, 2015

Choose a reason for hiding this comment

abusalimov commented Nov 19, 2015

abusalimov commented Dec 10, 2015

s0undt3ch commented Dec 11, 2015

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

s0undt3ch commented Dec 11, 2015

abusalimov commented Dec 11, 2015

Choose a reason for hiding this comment

abusalimov commented Dec 12, 2015

s0undt3ch commented Dec 12, 2015

s0undt3ch commented Dec 12, 2015

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

s0undt3ch commented Dec 12, 2015

abusalimov commented Dec 13, 2015

Choose a reason for hiding this comment

abusalimov commented Dec 23, 2015

s0undt3ch commented Dec 23, 2015

abusalimov commented Dec 23, 2015

s0undt3ch commented Dec 23, 2015

abusalimov commented Dec 26, 2015

s0undt3ch commented Jan 23, 2016

abusalimov commented Jan 23, 2016

s0undt3ch commented Jan 24, 2016