Add log-auto-indent option to control multiline formatting #5926

earthman1 · 2019-10-07T22:04:51Z

Allow selective auto-indentation of multiline log messages.

Supports command line option --log-auto-indent [value]
and config option log_auto_indent to set the default for all logging.

Supports passing kwarg extra={"auto_indent": [value]} to
calls to log.log() to specify auto-indentation behavior for
a specific entry in the log.

[value] can be:
* True or On - Dynamically auto-indent multiline log messages
* False or Off or 0 - Do not auto-indent multiline log messages
* [integer] - auto-indent multiline log messages by [integer] spaces

extra kwarg overrides the value specified on the command line or in the config.

Implements feature request #5515

nicoddemus

@earthman1 thanks a lot, overall a great and well written PR!

Please take a look at my comments and let us know your thoughts. 👍

changelog/5515.feature.rst

nicoddemus · 2019-10-07T22:55:29Z

src/_pytest/logging.py

    @staticmethod
    def _update_message(record_dict, message):
        tmp = record_dict.copy()
        tmp["message"] = message
        return tmp

+    def _get_auto_indent(self, record):


Can we add a docstring here please? It is not entirely obvious all that's being done here.

I also suggest turning this into a function:

def get_auto_indent(record, default_auto_indent) -> int:

Where default_auto_indent is self._auto_indent at the call site.

Then we can unittest this function in isolation and account for all the branches and cases it handles. 👍

Docstring: yes, I'll create that now.
Altering the method definition: Yes, I can make that static. Do you feel it is important to make the method public? To me it feels like it is private, but I don't know your views on calling private methods from the unittests.

With respect to the docstring, you indicated that the purpose for it is that "It is not entirely obvious all that's being done here." As I began to write it, it started to seem wordy, because I'm trying to address your concern. Do you really want something detailed?

More about the overall purpose of the method

Altering the method definition:

I meant to make it a function; the fact that it is public is not really relevant, because the module itself is not public (but it is OK to import the private module on our own test suite).

I changed this to a static method as requested, but I also added new test cases to get the code coverage up to 100% so the use case for making the method public seems less urgent now

src/_pytest/logging.py

nicoddemus · 2019-10-07T22:56:46Z

src/_pytest/logging.py

+        "--log-auto-indent",
+        dest="log_auto_indent",
+        default=None,
+        help="auto indent multiline messages passed to the logging module. accepts true|on, false|off or an integer",


I'm not sure we need to support on/off... any reason for it?

To confirm, you mean only support true/false and remove support for on/off?

No specific need to support on/off. If you'd like me to remove it, let me know.

To confirm, you mean only support true/false and remove support for on/off?

Exactly, sorry I wasn't clear. Let's remove it, no need to have support for two set of options. 👍

Thanks!

I ended up taking a different route with respect to this discussion. I discovered that there is a strtobool method in pytest's config module, which I simply imported and reused for this purpose, which means I don't need to hard-code the accepted values for the strings, and it will simply accept the same strings as all the config options.

It also happens to be that the standard for all pytest config options is to accept y/n, yes/no, t/f, true/false, on/off and 1/0, so now this option will follow that standard as well.

Great, good call

twmr

Thx for working on this @earthman1 !

twmr · 2019-10-08T17:17:16Z

changelog/5515.feature.rst

+``[value]`` can be:
+    * True or On - Dynamically auto-indent multiline log messages
+    * False or Off or 0 - Do not auto-indent multiline log messages
+    * [integer] - auto-indent multiline log messages by [integer] spaces


Great that you've added support for configuring the the indentation level explicitly!

s/integer/positive integer/ ?

I'd rather see a link from the changelog to docs, instead of having it expanded/explained that much there.
(people apparently (according to #5952 at least) will find it then in the changelog, and might see an out-of-date documenation)

s/integer/positive integer/ ?

Agreed

I'd rather see a link from the changelog to docs, instead of having it expanded/explained that much there.

Can you provide more detail what you'd like to see here, or perhaps the exact text you prefer? I'm not sure what you're looking for.

@earthman1
Not sure what's unclear.. the changelog basically documents the feature/change, while that should be in the docs themselves instead (where it gets updated in the future).

I.e. https://github.com/pytest-dev/pytest/blob/817a42d48fb00cf50553facecdbbc24dadabf36c/changelog/5515.feature.rst should go into https://github.com/pytest-dev/pytest/blame/914a9465aba501e776282961fb3317837772435d/doc/en/reference.rst#L1196, and then the changelog should link to that (IIRC that's not possible though due to pre-commit failing on it then.. #4283). So assuming #4283 is still a problem, it should just mention/describe the setting briefly, but not document it there.

twmr · 2019-10-08T17:22:18Z

changelog/5515.feature.rst

+and config option ``log_auto_indent`` to set the default for all logging.
+
+Supports passing kwarg ``extra={"auto_indent": [value]}`` to
+calls to ``log.log()`` to specify auto-indentation behavior for


What do you mean by log.log? Probably you mean logging.log from the stdlib, right? Please try to make this a bit clearer in the changelog entry.

You're right, of course. I'll change that

twmr · 2019-10-08T17:27:42Z

changelog/5515.feature.rst

+Supports command line option ``--log-auto-indent [value]``
+and config option ``log_auto_indent`` to set the default for all logging.
+
+Supports passing kwarg ``extra={"auto_indent": [value]}`` to


What is the motiviation for adding an auto_indent parameter to log.log? Do you want to configure auto_indent per log record?

yes, this adds per log line support, so that you can strategically turn it off when printing a preformatted table of trace info, for example.

@earonesty is correct. Sometimes it is good to leave it default on, and then strategically turn it off on a particularly long log entry that doesn't want to be pushed so far to the right, or to set the indentation position to a position that is suited to that entry

src/_pytest/logging.py

twmr · 2019-10-08T17:35:46Z

src/_pytest/logging.py

+        specified.
+
+        Any other values for the option are invalid, and will silently be
+        converted to "on".


Please document the meaning of the return value using the :returns: directive
sth like

:returns: indenation value, which can be -1 (automatically determine indentation) or 0 (auto-indent turned off) or >0 (explicitly set indentation position).

Will add that

twmr · 2019-10-08T17:45:17Z

src/_pytest/logging.py

+    add_option_ini(
+        "--log-auto-indent",
+        dest="log_auto_indent",
+        default=None,


Why do you set auto-indent by default to None and not to "true"?

My preference is to set the variables that represent options to None if the option is not specified, rather than to a valid value, so that the default condition can be distinguished from the user explicitly choosing the default. This can make a difference when there are multiple ways to specify the option, and have it fall back if the option was not explicitly set.

This may not specifically relate to the setting I'm working on, but I find it to be a good practice overall because it may not be clear up front whether or not distinguishing the default from an explicit choice equal to the default may be necessary later.

FTR I like this approach too.

Thx for the explaination.

twmr · 2019-10-08T17:47:26Z

src/_pytest/logging.py

+        elif default_auto_indent is not None:
+            in_auto_indent = default_auto_indent
+        else:
+            in_auto_indent = -1


This branch is only reachable if the user didn't specify a parameter to log-cli-level. Maybe we don't need distinguish between default_auto_indent being None and not-None.

twmr · 2019-10-08T17:54:22Z

src/_pytest/logging.py

+        if type(in_auto_indent) is int:
+            out_auto_indent = in_auto_indent
+        if type(in_auto_indent) is str:
+            if in_auto_indent.lower() == "true" or in_auto_indent.lower() == "on":
+                out_auto_indent = -1
+            elif in_auto_indent.lower() == "false" or in_auto_indent.lower() == "off":
+                out_auto_indent = 0
+            else:
+                try:
+                    out_auto_indent = int(in_auto_indent)
+                except ValueError:
+                    out_auto_indent = -1
+        elif type(in_auto_indent) is bool:
+            if in_auto_indent:
+                out_auto_indent = -1
+            else:
+                out_auto_indent = 0


Please move this code to a new method and call it in __init__, where you assign the return value to self._auto_indent and in _get_auto_indent. You can then change the implemenation of _get_auto_indent to

def _get_auto_indent(self, .....): if hasattr(record, "auto_indent"): # passed in from the "extra={}" kwarg on the call to log.log() out_auto_indent = self.TODO_NEW_METHOD(record.auto_indent) else: out_auto_indent = self._auto_indent return out_auto_indent

Since the above method is very simple you can also move it directly to def format.

I followed this advice in the latest iteration, including calling this code for the config option in the __init__, but I did not need to create a new method. Having moved the code to def format as you suggested, this left all the code that would have been moved to a new method already isolated in def _get_auto_indent, so this accomplished what I believe you had intended.

twmr · 2019-10-11T20:07:57Z

src/_pytest/logging.py

+    add_option_ini(
+        "--log-auto-indent",
+        dest="log_auto_indent",
+        default=None,


Thx for the explaination.

twmr · 2019-10-11T20:12:54Z

src/_pytest/logging.py

+        specified.
+
+        Any other values for the option are invalid, and will silently be
+        converted to "on".


earthman1 · 2019-10-11T21:00:57Z

Any suggestions how to resolve the codecov/changes failing check? I don't know what "1 file has unexpected coverage changes not visible in diff" means.

earthman1 · 2019-10-11T21:04:08Z

After checking, my diff has 100% code coverage, and I don't see how I might have reduced coverage elsewhere

earthman1 · 2019-10-15T14:34:43Z

I rebased from the features branch and force pushed in order to fix the base that codecov was comparing against. It still does not pass codecov, so a little assistance getting this approved PR over the finish line would be greatly appreciated

blueyed · 2019-10-15T15:02:54Z

The changes to junitxml in the coverage report are due to flakiness (see #5959). You can ignore it here.

blueyed · 2019-10-15T15:54:49Z

testing/logging/test_formatter.py

+    record.auto_indent = False
+    output = ai_on_style.format(record)
+    assert output == (
+        "dummypath                   10 INFO     Test Message line1\n" "line2"


This is hard to read / confusing.
Please consider using .splitlines() instead and comparing lists instead.
Also below.

If black gets in your way here you can also use # fmt: off … # fmt: on..

This is the way the test was written before I introduced my feature change. I merely duplicated the check within the existing test, and adjusted it to check for the new behavior

This is all new code, and I do not see "…line1\n" "line2" being used anywhere before?!

lines 58-61

Personally, I agree the current behavior might not be a desirable default for some ... but I'd be wary of changing it out from under existing users. For example: if people have done curious things with their ci logs, like parsing them and loading them into splunk, changing the default would cause those same people may have to modify their parsers. I'm all for keeping the current default ... not because it's particularly more or less sane, but because leaving defaults the same is often a good choice.

@earonesty
Thanks for the feedback. I've thought we only changed this recently, but it is in 4.6.0 already (c8d23c2).

But according to #5312 (comment) it does not only affect the output, but also existing tests where .text is different then..! (not sure if that is addressed here when changing the output, and/or was fixed inbetween already).

Therefore (and in general) I'd be still +1 to restore the behavior before 4.6.0 by default (i.e. change the defaults in this PR). It is unfortunate that it would change back and forth then, but seems to be better / more sane in the long term.
I assume @asottile agrees here (using pytest as a tool that should not do too much magic)?

@Thisch
What do you think?

I agree with @blueyed here. We should restore the default behavior (before 4.6) and at some point think about moving the multiline code (and the colored log formatter as well) to a separate pytest plugin, because this would simplify the logging plugin a bit (not sure if this simplification is worth the effort, though).

And as a justification of the restoration of the old default value, I would only say in the changelog that
"It is better to activate new features that may lead to broken tests explicitly instead of implicitly."

nicoddemus

Thanks a lot for the great contribution @earthman1!

nicoddemus · 2019-10-15T22:58:44Z

src/_pytest/logging.py

+        "--log-auto-indent",
+        dest="log_auto_indent",
+        default=None,
+        help="auto indent multiline messages passed to the logging module. accepts true|on, false|off or an integer",


Great, good call

src/_pytest/logging.py

earthman1 · 2019-10-22T14:09:56Z

Are there any remaining tasks with respect to the PR?

blueyed · 2019-10-22T16:41:15Z

From my side: #5926 (comment) and #5926 (comment).

earthman1 · 2019-10-22T21:25:37Z

I made the change to the changelog/reference.rst

earthman1 · 2019-10-22T21:26:03Z

Let me know if there are any remaining tasks for me

blueyed · 2019-10-22T21:36:34Z

Thanks for the doc/changelog update.
I am still in the camp to have the old behavior by default (from before you were forced to create these options for it in the first place - #5926 (comment)). Therefore I'll at least not approve/merge it myself - JFI.

earthman1 · 2019-10-22T21:52:53Z

Any suggestion how to proceed?

earthman1 · 2019-10-22T21:56:02Z

Permit to propose a solution to the current obstacle. I will create a second PR that changes the default from true to false, and then once that PR looks good to you, you can feel better about merging this improvement, and still debate that issue, isolated to the PR that effectuates that specific change.

blueyed · 2019-10-22T22:11:29Z

Why not change it here already?
As far as I can see it cannot be changed before this is merged, since it won't be there already - or do I misunderstand?

earthman1 · 2019-10-22T22:20:54Z

I can change it here, but I am under the impression that changing the default is a matter of further discussion. If we permit the configurability of auto-indentation to be isolated from the changing of the default, that allows this merge to go in without waiting for the resolution of that discussion.

Having a separate PR up that changes the default, that is a branch off of optional-multiline allows it to successfully merge after this PR merges. The hope is that this will give you the confidence that the discussion is still alive, but without the necessity of holding up a PR that is arguably not related to what the default behavior is (or what it should be)

earthman1 · 2019-10-22T23:10:40Z

It looks like there is a consensus building around reverting the default from True to False. I anticipate to submit this change tomorrow.

earthman1 · 2019-10-23T14:18:11Z

The default has been changed to log_auto_indent off. Let me know if you have any further comments, questions or requests.

twmr

Thx so much for incorporating our suggestions. I still only have some minor suggestions.

twmr · 2019-10-23T17:39:02Z

doc/en/reference.rst

+    ``[value]`` can be:
+        * True or On - Dynamically auto-indent multiline log messages
+        * False or Off or 0 - Do not auto-indent multiline log messages
+        * [positive integer] - auto-indent multiline log messages by [value] spaces


Please mention that auto-indentation is turned off by default.

twmr · 2019-10-23T17:42:39Z

doc/en/reference.rst

+    auto-indentation behavior for all logging.
+
+    ``[value]`` can be:
+        * True or On - Dynamically auto-indent multiline log messages


Maybe add quotes around On.

twmr · 2019-10-23T17:42:53Z

doc/en/reference.rst

+
+    ``[value]`` can be:
+        * True or On - Dynamically auto-indent multiline log messages
+        * False or Off or 0 - Do not auto-indent multiline log messages


Same for Off

twmr · 2019-10-23T17:43:47Z

doc/en/reference.rst

+    Some examples of using the ``extra`` kwarg might be:
+
+    .. code-block:: python
+
+        import logging
+
+        log = logging.getLogger(__name__)
+
+
+        def test_multiline():
+            log.debug("line 1\nline 2 indented", extra={"auto_indent": True})
+            log.warning("line 1\nline 2 not indented", extra={"auto_indent": "off"})
+            log.log(
+                logging.ERROR, "line 1\nline 2 indented by 5 spaces", extra={"auto_indent": 5}
+            )


I'm not sure if we need an usage example for the extra kwarg. I think the paragraph starting at L1213 explains the feature pretty well and doesn't need an additional code block.

earthman1 · 2019-10-23T20:31:22Z

As before, please let me know if there are any remaining tasks or questions. Thx

blueyed · 2019-10-23T21:20:55Z

changelog/5515.feature.rst

+Alters the default for auto-indention from ``on`` to ``off``,
+reverting to the behavior prior to v4.6.0. This reversion to earlier
+behavior was done because it is better to activate new features that
+may lead to broken tests explicitly rather than implicitly.


Sorry to be annoying, but I think the changelog should clearly mention that this restores the (older) behavior.

Can you provide the language you need? I felt that "...reverting to the behavior prior to v4.6.0. This reversion to earlier behavior was done because..." did clearly indicate that we are restoring old behavior.

Sorry to be annoying, but I think the changelog should clearly mention that this restores the (older) behavior.

You're not annoying, you're committed to quality.

I changed the wording of the changelog to be closer to the wording in your request. Please let me know if I can improve this further, or if there are any other requests you may have.

blueyed

LGTM, thanks!
Delegating to @Thisch (reviewed again already) @nicoddemus (please check if you still like it).

earonesty · 2019-10-29T12:27:21Z

Just pointing out and cementing the fact that at 100 mentions, this is the most commented pull req of all 2000+ reqs in this repo's history.

twmr · 2019-10-29T18:59:21Z

@nicoddemus I would like to merge this PR. Any objections/suggestions?

earthman1 · 2019-10-29T19:26:49Z

Just pointing out and cementing the fact that at 100 mentions, this is the most commented pull req of all 200+ reqs in this repo's history.

Wow, I hadn't noticed that. Funny

link: PRs sorted by most commented

I think it's more like 2,600 or so PRs at this point. The original PR had 8 comments :-)

earthman1 · 2019-11-05T14:36:13Z

Haven't seen any activity on the PR in a week, just checking in

blueyed · 2019-11-05T23:34:49Z

Yeah...
I was waiting for others to (re-)approve, but apparenently they are busy with other things.

Since @Thisch approved a week ago already, and I am very happy for you to have understood my commitment to quality I'm going to merge it now.

Thanks a lot! (also to everyone having contributed to the constructive part of the 100+ comments)

earthman1 mentioned this pull request Oct 7, 2019

Option to disable cli log indentation #5515

Closed

nicoddemus reviewed Oct 7, 2019

View reviewed changes

nicoddemus requested a review from twmr October 7, 2019 22:57

twmr suggested changes Oct 8, 2019

View reviewed changes

twmr approved these changes Oct 11, 2019

View reviewed changes

blueyed reviewed Oct 15, 2019

View reviewed changes

nicoddemus approved these changes Oct 15, 2019

View reviewed changes

blueyed reviewed Oct 16, 2019

View reviewed changes

src/_pytest/logging.py Outdated Show resolved Hide resolved

earonesty reviewed Oct 16, 2019

View reviewed changes

src/_pytest/logging.py Outdated Show resolved Hide resolved

twmr suggested changes Oct 23, 2019

View reviewed changes

twmr approved these changes Oct 23, 2019

View reviewed changes

blueyed reviewed Oct 23, 2019

View reviewed changes

Add log-auto-indent option to control multiline formatting

1f5b454

earthman1 requested a review from blueyed October 25, 2019 21:04

blueyed reviewed Oct 26, 2019

View reviewed changes

earthman1 requested a review from nicoddemus October 31, 2019 16:41

blueyed merged commit e7320c6 into pytest-dev:features Nov 5, 2019

Add log-auto-indent option to control multiline formatting #5926

Add log-auto-indent option to control multiline formatting #5926

Conversation

earthman1 commented Oct 7, 2019 • edited Loading

nicoddemus left a 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

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

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

twmr left a 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

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

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

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

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

Choose a reason for hiding this comment

earthman1 commented Oct 11, 2019

earthman1 commented Oct 11, 2019

earthman1 commented Oct 15, 2019

blueyed commented Oct 15, 2019

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

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

twmr Oct 22, 2019 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

nicoddemus left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

earthman1 commented Oct 22, 2019

blueyed commented Oct 22, 2019

earthman1 commented Oct 22, 2019

earthman1 commented Oct 22, 2019

blueyed commented Oct 22, 2019

earthman1 commented Oct 22, 2019

earthman1 commented Oct 22, 2019

blueyed commented Oct 22, 2019

earthman1 commented Oct 22, 2019

earthman1 commented Oct 22, 2019

earthman1 commented Oct 23, 2019

twmr left a 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

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

earthman1 commented Oct 7, 2019 •

edited

Loading

twmr Oct 22, 2019 •

edited

Loading

earonesty commented Oct 29, 2019 •

edited

Loading