classification
Title: Add TRACE level to the logging module
Type: enhancement Stage: resolved
Components: Library (Lib) Versions: Python 3.7
process
Status: closed Resolution: wont fix
Dependencies: Superseder:
Assigned To: vinay.sajip Nosy List: haypo, pmpp, r.david.murray, rhettinger, vinay.sajip
Priority: normal Keywords: patch

Created on 2017-10-09 12:29 by haypo, last changed 2017-10-14 14:10 by r.david.murray. This issue is now closed.

Pull Requests
URL Status Linked Edit
PR 3930 closed haypo, 2017-10-09 12:49
Messages (12)
msg303945 - (view) Author: STINNER Victor (haypo) * (Python committer) Date: 2017-10-09 12:29
The logging module has already 5 log levels: CRITICAL, ERROR, WARNING, INFO, DEBUG.
https://docs.python.org/dev/library/logging.html#logging-levels
(I don't count NOTSET, I don't consider it to be "usable", at least not in an application or a library.)

For a large application, sometimes we need to a 6th level since DEBUG might be too verbose for some customers (random value: 1 MiB of log per minute). The OpenStack project has 2 additional logging levels: TRACE and AUDIT. See the Oslo Log project used by all OpenStack projects:

https://github.com/openstack/oslo.log/blob/master/oslo_log/handlers.py#L39

The typical usage for TRACE is to log a Python traceback when an exception is logged:

logger.debug("Oops: something bad happened! %s", exc)
for line in my_exception_formatter(exc):
   logger.trace(line)

In software development, "trace" term is commonly associated to "debug traces", as in "How to get debug traces?". Or more commonly in Python: "traceback" or "stack trace".

An additional level helps to filter logs, but also to colorize logs differently.

--

I don't propose to add a new AUDIT level since it's not well defined and it's less popular in OpenStack. For example, the Oslo Log module adds a new logger.trace() method, but no logger.audit().
msg303947 - (view) Author: STINNER Victor (haypo) * (Python committer) Date: 2017-10-09 12:50
Attached PR 3930 adds logging.TRACE, logging.trace() and logging.Logger.trace().
msg303949 - (view) Author: STINNER Victor (haypo) * (Python committer) Date: 2017-10-09 13:10
Other references to a TRACE logging level:

* SaltStack: trace = 5
  https://docs.saltstack.com/en/latest/ref/configuration/logging/#log-levels

* autologging.TRACE = 1: "A custom tracing log level, lower in severity than logging.DEBUG."
  autologging: "Autologging eliminates boilerplate logging setup code and tracing code, and provides a means to separate application logging from program flow and data tracing."
  http://pythonhosted.org/Autologging/autologging.html#autologging.TRACE

* robot.logger.TRACE and robot.logger.trace()
  https://robot-framework.readthedocs.io/en/2.9.2/_modules/robot/api/logger.html
  https://robot-framework.readthedocs.io/en/2.9.2/autodoc/robot.api.html#log-levels

* "I'd like to have loglevel TRACE (5) for my application (...)"
  https://stackoverflow.com/questions/2183233/how-to-add-a-custom-loglevel-to-pythons-logging-facility

--


FYI while searching users of "TRACE" log level, I also found the other log levels:

* "NOTE" < DEBUG
* "FATAL" = CRITICAL
* "profile" = 15 < INFO, but 15 > DEBUG
* "garbage" = 1 < DEBUG

Again, I don't think that these ones are interesting.
msg303950 - (view) Author: STINNER Victor (haypo) * (Python committer) Date: 2017-10-09 13:24
More references to TRACE logging level:

* "CUSTOM_TRACE = 5 # Mapping for zLOG.TRACE" in Zope zLOG
  https://github.com/zopefoundation/zLOG/blob/master/src/zLOG/EventLogger.py#L29

* Runlevel = stem.util.enum.UppercaseEnum('TRACE', 'DEBUG', 'INFO', 'NOTICE', 'WARN', 'ERROR')
  TRACE, DEBUG, INFO, NOTICE, WARN, ERR = list(Runlevel)
  https://stem.torproject.org/_modules/stem/util/log.html

* "TRACE = 5 # Trace log level."
  "An extension of Python's option parser."
  https://github.com/mikeorr/WebHelpers2/blob/master/unfinished/logging_optparse.py#L14

* "TRACE = 5"
  http://www.taurus-scada.org/en/latest/_modules/taurus/core/util/log.html

* "TRACE = 9"
  "bokeh: Interactive plots and applications in the browser from Python"
  https://pypkg.com/pypi/bokeh/f/bokeh/util/logconfig.py

* "With custom log levels: (...) TRACE = 5" (an example in the doc)
  https://pypi.python.org/pypi/colorlog

Note: Zope zLOG also has a "CUSTOM_BLATHER = 15 # Mapping for zLOG.BLATHER" level.
msg304214 - (view) Author: Raymond Hettinger (rhettinger) * (Python committer) Date: 2017-10-12 07:48
I vote against this on the ground that five levels have sufficed for a long and that the need for finer distinctions almost never arises in practice.  There would be an ongoing mental cost to making users learn and think about finer levels of distinction.
msg304226 - (view) Author: STINNER Victor (haypo) * (Python committer) Date: 2017-10-12 10:05
Raymond Hettinger: "... the need for finer distinctions almost never arises in practice"

I gave a list of 10 projects which are alreading using widely the 6th TRACE level.

In this list, I consider that OpenStack and SaltStack are two big and serious projects which justify to add the TRACE level in the stdlib. It will avoid these projects to have to "patch" the stdlib for their need.
msg304229 - (view) Author: pmpp (pmpp) Date: 2017-10-12 11:47
As a dumb user I vote in favor of this on the ground that five levels is not sufficient for a long and that the need for finer distinctions already arose for me in practice.  Till i overcame the mental cost to think, learn and *find time* on how to make a finer level of distinction to work.

line tracing logging is a level on its own and doesn't fit with provided ones which are *too simple*.

--

If python is "battery included". It's time to provide a multiplatform charger ...
msg304304 - (view) Author: Raymond Hettinger (rhettinger) * (Python committer) Date: 2017-10-13 02:52
No need to be brusque with me.  Vinay is the decision maker on this.

Overall, this seems rehash and second guess the discussions and decisions made 15 years ago when PEP 282 was accepted.  At that time, it was decided that five levels had advantages for learnability and usability, but that the levels should be extendable to cover more specialized uses:

    >>> import logging
    >>> SEMI_IMPORTANT = 35
    >>> logging.addLevelName(SEMI_IMPORTANT, 'SEMI_IMPORTANT')
    >>> logging.log(SEMI_IMPORTANT, 'request backlog getting high')
    SEMI_IMPORTANT:root:request backlog getting high

This effortless extendability let us avoid adding the whole zoo of names sometimes used in other projects (FATAL, TRACE, NOTICE, FINE, FINER, FINEST).  As far as I can tell, this module has a 15 year track record of success and was well thought-out from the outset.  So there is no reason to suddenly be so insistent that the module must change to accommodate your world view of how everyone else should prioritize their log entries.

As a teacher, project leader, and coach, one thing I really like about Vinay's design is that people seem to easily and naturally assign the correct rank order to the existing five levels.  Today, I asked some engineers where TRACE or NOTICE would fit in and they were unsure.  This indicates that adding new levels will impact usability and make users worse off.
msg304308 - (view) Author: pmpp (pmpp) Date: 2017-10-13 05:21
Sorry, i didn't mean to be rude. Just wanted to pick your attention because i think you miss the point:  logging as is it with its levels is perfect for *log messages*.
Review the typical usage shown and you'll see that tracing level is for logging tracebacks : the debug message is separate. Traces just don't fit on standard log output, they clutter and obviously have a format of their own. 
As a user i see TRACE as context for logging.exception when it has nothing to do with errors or verbosity.
msg304318 - (view) Author: Vinay Sajip (vinay.sajip) * (Python committer) Date: 2017-10-13 07:41
As Raymond has said: though it might appear reasonable to add a TRACE level from the numerous examples that Victor has given, in practice it is hard enough to know when a particular level should be applied. Victor says "we need to a 6th level since DEBUG might be too verbose" - but as the PR is currently constituted, enabling the TRACE level would output DEBUG messages too, and so be even more verbose than just DEBUG! In this case I feel that, when considering the number of levels, "less is more".

For specific applications different levels might be desirable, and the logging system makes this possible, though not at the level of convenience of having a trace() method on loggers. However, it's easy enough to provide your own subclass with that method, if you really need it that badly. Of course you can currently also do logger.log(TRACE, ...) without the need for any subclass or need to "patch the stdlib" (as per Victor's comment).

This is one of those areas where tastes differ - and it is IMO really just a matter of taste. The five levels we have presently are based on what was considered best practice when the logging module was added to Python, and it specifically eschewed adopting prior art where more levels were available (e.g. syslog). The documentation gives a clear rationale for when to use what level:

https://docs.python.org/2/howto/logging.html#when-to-use-logging

and this seems of reasonably universal applicability across projects.

Given that individual projects *can* provide additional levels according to their need, I feel that there is no need for a TRACE level in the stdlib; as Raymond has pointed out in msg304304, the current levels are easy to understand when to apply, and finer levels invariably lead to different opinions on when to use them, due to essentially being matters of taste.
msg304337 - (view) Author: STINNER Victor (haypo) * (Python committer) Date: 2017-10-13 13:29
Vinay:
> I feel that there is no need for a TRACE level in the stdlib

Ok, that's fine.

I just pushed the idea of someone on IRC. Since I had the same idea once, I tried, but I lost :-) I can easily survive without TRACE in the stdlib ;-)


Vinay:
> Victor says "we need to a 6th level since DEBUG might be too verbose" - but as the PR is currently constituted, enabling the TRACE level would output DEBUG messages too, and so be even more verbose than just DEBUG! In this case I feel that, when considering the number of levels, "less is more".

Oh, I'm not sure that I explained my point correctly, since someone else on IRC told me that he misunderstood.

My point is that logs have different consumers who have different expectations and usages of the logs.

In my case, the customer may want to go to up to the DEBUG level "by default" to collect more data on failures. Enabling TRACE would produce too many logs and should be restricted to the most tricky bugs where you cannot guess the bug only with the DEBUG level.

I tried to explain that if you are putting all debug traces at the DEBUG level, you may produce 10 MB of log per minute (arbitrary number for my explanation). But producing 10 MB per machine in a large datacenter made of thousands of servers can lead to practical storage issues: too many logs would fill the log partition too quickly, especially when logs are centralized.

The idea is to reduce debug traces to 10% at the DEBUG level, and put the remaings traces at the TRACE level. For example, you can imagine to log an exception message at DEBUG, but log the traceback at TRACE level. The traceback is likely to produce 10x more logs.

The TRACE level is only enabled on-demand for a short period of time on a few selected servers.

Technically, you can already do that INFO and DEBUG levels. But in OpenStack, these levels are already "busy" with enough messages and we needed a 6th level :-)

(I don't want to reopen the discssion, just to make sure that I was correctly understood ;-))
msg304393 - (view) Author: R. David Murray (r.david.murray) * (Python committer) Date: 2017-10-14 14:10
I'm not arguing against the rejection, but I want to mention a point in relation to Raymond's statement "five levels have sufficed for a long and that the need for finer distinctions almost never arises in practice".  In thinking about my own codebase, I have only one project where I added a notice level, and none in which I currently have a TRACE level although I think I used it as described below in one during development.

If logging had had TRACE built in, I would have used it in almost every project I've written.  Instead, I squash everything into the DEBUG level, and that results in two things: overly verbose debug logs, and still having to go in and add extra temporary debug logging statements to debug hard problems.

I don't think this is a terrible thing.  The "pain" of it only once rose to the level where I added a TRACE level to my program. My point is that the lack of TRACE (or NOTICE) getting added to projects on a common basis, rather than meaning the need for the distinction "almost never arises", means instead that the need for them is less pressing than the small pain of adding them.

I will make one argument in favor of adding a TRACE level, but I don't know that it is enough to shift the balance.  That argument is that if I had a TRACE level built in, instead of adding and deleting extra temporary debug logging statements during a debugging cycle, I would add them at the TRACE level and *leave them in*, at least until I was ready to ship the code.  Not having to add and remove them, and then almost always end up re-adding and re-removing them, would speed up my debugging cycle by a non-trivial amount.  Why don't I add a TRACE level and do this?  It feels like too much of a pain "just to debug this", but then I wind up coming up against that decision again when working on the next bug, and the next..and each time it is too much of a pain to add TRACE "just for this bug".  

So, having TRACE built in might speed up debugging cycles, because programmers are lazy :)

Having made this conscious as a result of thinking about this issue, I may start adding TRACE to my projects more often :)
History
Date User Action Args
2017-10-14 14:10:08r.david.murraysetnosy: + r.david.murray
messages: + msg304393
2017-10-13 13:29:51hayposetmessages: + msg304337
2017-10-13 07:41:34vinay.sajipsetstatus: open -> closed
type: enhancement
messages: + msg304318

resolution: wont fix
stage: patch review -> resolved
2017-10-13 05:21:44pmppsetmessages: + msg304308
2017-10-13 02:52:04rhettingersetmessages: + msg304304
2017-10-12 11:47:40pmppsetnosy: + pmpp
messages: + msg304229
2017-10-12 10:05:31hayposetmessages: + msg304226
2017-10-12 07:48:04rhettingersetassignee: vinay.sajip

messages: + msg304214
nosy: + rhettinger
2017-10-09 13:24:03hayposetmessages: + msg303950
2017-10-09 13:10:29hayposetmessages: + msg303949
2017-10-09 12:50:05hayposetnosy: + vinay.sajip
messages: + msg303947
2017-10-09 12:49:23hayposetkeywords: + patch
stage: patch review
pull_requests: + pull_request3905
2017-10-09 12:29:21haypocreate