logger: Use a more _pythonic_ logging

[ghost]

• Uses a formatter for coloring output
• Move the progress_aware decorator logic to the logger itself
• Refactor modules so each one uses their own instance of a logger
• Prefer logger.exception over logger.error
• tests: use pytest caplog instead of custom mock (close test: unify logger output mocking #1797)

Close #1753

---

[efiop]

Why couldn't self._caplog.at_level down below clear log by default?

[ghost]

_caplog.at_level is only a context manager to set the level of a logger, and changing the level shouldn't affect the previous log, what caplog.clear() does is to remove all the LogRecord entries saved on caplog.records.

[efiop]

@MrOutis yeah, but why would you use at_level and not use clear() before it? I'm not saying at_level should do that perse, but it feels like it would be convenient to have something that would reset it automatically when you are capturing log with with. What do you think?

[ghost]

I guess at_level is to test logging specific info, for example, it is used in test_logger.py for logic that depends on the current level (outputting the traceback on an error only when --verbose is specified).

In this test, we were running the add command before, creating some unwanted logs for our test:

    def test(self):
        ret = main(["add", self.FOO])
        self.assertEqual(ret, 0)

That's why I do:

        self._caplog.clear()

Now, the at_level thing is because the previous test was asserting that the output should contain Warning: <message>, to maintain compatibility, I used _caplog.at_level to make sure the message didn't come from debug or info:

        with self._caplog.at_level(logging.WARNING, logger="dvc"):
            ret = main(["tag", "remove", "v1", "foo.dvc"])
            self.assertEqual(ret, 0)

        assert "tag 'v1' not found for 'foo'" in self._caplog.text

I don't think this is always the case, as sometimes we would be trying to test something logged by info. Also, I'd prefer to leave it as it is, you can read and write tests without having to know beforehand about a set_level_and_clear method, for example 😛

[efiop]

Looks great, @MrOutis ! Could you show us how dvc commands (e.g. dvc init) look like now? For example with asciinema.

[pared]

<3 especially for removing MockLoggerHandlers and ConsoleFontColorsRemover. Btw, I noticed that you did not remove those classes, maybe remove tests/utils/logger.py ?

just removed progress_aware :)

[pared]

@MrOutis And what about tests/utils/logger.py? :)

[ghost]

😅 missed that one, @pared , thanks! I'll remove it on the next commit

[ei-grad]

1. I'd like to replace all the .format() things with the logger's own ability to do the message formatting. This is not so critical for the .exception() and .error(), but would really improve overall dvc performance if it would be replaced for .debug() calls.

2. I think it could be better to make some explicitly named loggers like

cli_logger = logging.getLogger("dvc.cli")
remote_logger = logging.getLogger("dvc.remote")
repo_logger = logging.getLogger("dvc.repo")

somewhere in dvc/logger.py instead of putting the logger = logging.getLogger(__name__) in each separate module. But now you should know better than me does it make sense at all and which loggers set could we need to improve the testing experience and make the logging configuration easier and more flexible.

[ei-grad]

The string formatting routines shouldn't be used in the logger method invocations. This should be rewritten with:

"failed to commit%s", (" " + target) if target else ""

[ghost]

totally, @ei-grad ; I delayed this change because the whole code base is currently using the brace style: "hello {}".format("world"), sadly, on 2.7 the logger doesn't support braces, but it does on 3.x maybe we should wait a little bit to embrace this change.

[ei-grad]

Suggested change

	logger.exception("failed to unset '{}'".format(self.args.name))
	logger.exception("failed to unset %r", self.args.name)

[ei-grad]

Suggested change

	logger.exception("failed to show '{}'".format(self.args.name))
	logger.exception("failed to show %r", self.args.name)

[ei-grad]

Suggested change

	"failed to set '{}.{}' to '{}'".format(section, opt, value)
	"failed to set '%s.%s' to %r", section, opt, value,

[ei-grad]

Good work, btw! Thanks! Really like the dvc logging to go this way.

[ghost]

I think it could be better to make some explicitly named loggers like

@ei-grad , that's a great suggestion, a lot of projects use that approach. My thoughts are that having getLogger(__name__) give us a more granular control (at the module level), so if we want to modify how the logger behaves for state.py (where the SQL queries that @dmpetrov noticed in #1753 comes from), we can add some config targeting dvc.state. Also, from the maintainer perspective, you don't need to decide what logger to use, it would always be getLogger(__name__).

[efiop]

@MrOutis #1831 is merged, please rebase this PR on top of master. 🙂

ei-grand I'll open a new issue to keep track of this refactor

[ghost]

@efiop , ready ! 😃

[efiop]

🔥 Thank you!