Skip to content

HTTPS clone URL

Subversion checkout URL

You can clone with HTTPS or Subversion.

Download ZIP

Loading…

Should not log to the root logger #53

Closed
mackstann opened this Issue · 19 comments

8 participants

@mackstann

Tornado should log to its own logger, so that the output can be properly separated, filtered, etc., from the output of the program using tornado. I'm seeing this in httpclient.py specifically.

@rferreira

I should have this fixed in my fork. Let me know what you think and feel free to pull.

@enaeseth

Just ran into this issue. Tornado really should follow the guidelines for logging from libraries in the documentation for the Python logging module.

@ayust

Bumpity bump bump. Would really like to see this fixed, but we're not yet running a version of Tornado where a local patch would apply cleanly here. We may be upgrading soon, though, and it'd be really cool to upgrade to something which didn't have this issue.

@rferreira

I'll rebase my patch and make a pull request...

@bdarnell
Owner

Just noticed that I'm not getting emails for this bug since I haven't commented on it. The out-of-the-box behavior of the logging module is very bad when non-root loggers are used (this has finally been fixed in python 3.2). Since the IOLoop catches all exceptions and logs them, it is very important that log output be visible by default. As far as I can tell, this means either using the root logger or configuring a log handler at import time (which is tricky to do without conflicting with the application's log configuration).

Besides, a separate logger object per package/module seems like the wrong design to me: separate loggers should be used for semantically different information (e.g. Application.log_request should perhaps go to a different logger), but I think general warning/debug logs should all go to a single Logger with Filters (which may look at the LogRecord's module attribute) used to control verbosity.

@mitchellh

bdarnell,

Thanks for commenting. Its good to see that this bug is bumped. I would like to second this request. To address your concerns directly @bdarnell:

Since the IOLoop catches all exceptions and logs them, it is very important that log output be visible by default. As far as I can tell, this means either using the root logger or configuring a log handler at import time (which is tricky to do without conflicting with the application's log configuration).

I understand what you're saying here and Python's default behavior may be unfortunate, but using the root logger is generally a big no-no for any reason. In the above case, why not just print exception data to stdout by default? At the same time, always log to the tornado logger, for those of us who properly configure log handlers.

Printing to stdout would be far less intrusive than abusing the root logger, in my opinion, since no production system would ever use stdout as a proper log location, it would just be useful during development. For production, proper handlers will be attached to loggers.

Besides, a separate logger object per package/module seems like the wrong design to me: separate loggers should be used for semantically different information (e.g. Application.log_request should perhaps go to a different logger), but I think general warning/debug logs should all go to a single Logger with Filters (which may look at the LogRecord's module attribute) used to control verbosity.

This is what namespacing is for, and it works extremely well. For example, if each module had its own logger namespaced properly such as tornado.web and tornado.ioloop and tornado.web.handler and so on, then you could easily create a single filter/formatter/handler for the tornado logger and all tornado output would be logged. Additionally, if you want only a single Tornado module's output, then that is definitely easy as well.

Polluting the root logger makes filtering proper log messages much, much harder. :(

Please, please reconsider this issue. Loggers have namespaces for a great, useful reason, and using the root logger is really frustrating. At the very least, please make this configurable in some way (this would maintain backwards compatibility, if you so please).

I would gladly create a patch for this, but I do want to see more support for it before I would put forward any work.

Best,
Mitchell

@bdarnell
Owner

It definitely shouldn't print to stdout in addition to logging - no production system should use stdout as a logging destination, but production systems capture stdout anyway just in case, and this is not ideal since the mechanisms used are often inefficient or have poor support for rotation.

It's not even a question of root vs non-root logger objects, since it's not the root logger that automatically configures itself, but the top-level logging.{error,warning,info} functions. (unless you want to use the logging module itself as the "logger" object).

Can you give an example of the kind of configuration you'd like to make?

@ayust

@bdarnell - perhaps put a wrapper around logging for tornado, with a module-level function that could be called to specify a logger for tornado to use? By default it could use the root logger (for those who don't want to deal with the poor default handling of non-root loggers), but those who wanted to be able to clean up their logs would then at least have the ability to override such behavior (without modifying the tornado package).

@slingamn

It seems like Tornado could log to properly namespaced loggers, and then by default it could manually call logging.basicConfig (the side effect of using the module-level log functions that sets up the stderr handler). And then this call would be disabled by configuring logging=None, which is the current mechanism for disabling modification of the logging module.

Just for kicks, I implemented this at [https://github.com/slingamn/tornado/compare/logging]. Interested?

@bdarnell
Owner

But where to invoke basicConfig? It doesn't do any good to call basicConfig from the options module (and in fact it is harmful to do it where you added the call, since calling basicConfig before enable_pretty_logging results in double output), since apps that use tornado.options already get a sane logging configuration by default. The problem is for apps that don't use tornado.options. The basic requirement is that the following script should print a useful error message:

from tornado.ioloop import IOLoop
IOLoop.instance().add_callback(lambda: 1/0)
IOLoop.instance().start()
@slingamn

That makes sense. At the cost of slightly violating the encapsulation of logging (by reading logging.getLogger().handlers), could we move the check to IOLoop.start()?

See the now-updated branch in my fork, or this commit: shivaram/tornado@8b862a6

@slingamn

Sorry, wrong link: slingamn/tornado@8b862a6

@bdarnell
Owner

Calling basicConfig from IOLoop.start seems reasonable - that's where it becomes crucial to have some sort of logging configuration. However, there are some places where we currently log stuff before an IOLoop is started. These are mostly rare error cases (like trying to use set_blocking_log_threshold on a platform without the signal module), although the logging in process.py occurs in normal use (but I kind of doubt that the default log setup is multi-process safe anyway, so maybe that's OK).

So that gives us a way to move to non-root loggers without significant degradation from the status quo, although I'd still like to see an example config from some real application to demonstrate how distinct loggers are better than the alternative. :)

Finally, I'd like to suggest using a single getLogger('tornado') for all tornado logging instead of getLogger(__name__). Since the whole point of the exercise is to enable better filtering of logs, this means that the logger that emits certain log lines can no longer be considered just an implementation detail, while log messages can and do move between files as a result of routine refactorings.

@slingamn

I work on an application that uses Tornado extensively, and which sets the root logger to DEBUG in development. However, we find that some of Tornado's DEBUG-level messages are too verbose and make other messages difficult to read. My plan is to apply the following setting in development:

logging.getLogger('tornado').setLevel(logging.INFO)

which will suppress the DEBUG messages from Tornado while leaving our own DEBUG messages.

I think it's not necessary to use getLogger('tornado') for everything. Because of the log propagation system, operations done by the user to getLogger('tornado') (e.g., setting the level, attaching a handler) will still do the Right Thing to, e.g., getLogger('tornado.iostream').

Also, it's conceivable that someone could specifically wish to see messages from an important core module such as tornado.ioloop, while being less interested in messages from utility code such as tornado.httpclient. Using getLogger(__name__) preserves the possibility of doing this, without any significant drawbacks that I can see.

Here's a patch on top of the current master: [https://github.com/slingamn/tornado/compare/logging_2]. (I'd make a pull request for it, but I'm getting 404s from GitHub.)

@bdarnell
Owner

OK, so it sounds like you still want a single output stream, but filtered by module. I'd argue that this should be done with a logging.Filter rather than creating separate logger objects, but it's unfortunate that filters are so poorly integrated into the rest of the logging module. I use something like https://gist.github.com/3118509, but it does have the drawback of not being introspectable (via isEnabledFor).

As for getLogger('tornado') vs getLogger(__name__): I don't feel strongly about it, but it's a question of public API commitments vs implementation details. Logging from tornado.ioloop is more important than other modules not because ioloop is a "core" module, but because logging from IOLoop often indicates a bug in user code rather than coming solely from tornado. This "run callback and log message on error" pattern could easily get factored out into a separate function to be shared by IOLoop and other tornado code. Module names are already available to Filters, but so are line numbers so it's pretty clear that you're dealing with implementation details.

If we have finer-grained logging than just getLogger('tornado'), I'd rather do it right and create loggers based on semantics rather than just mimicking the module structure. There are at least three logical categories: exceptions from user code (caught in IOLoop and elsewhere), web request logs, and general tornado-internal logging.

@slingamn

I don't have strong feelings either. [https://github.com/slingamn/tornado/compare/logging_3] is the patch after

 ls tornado/*.py | xargs sed -i s/getLogger\(__name__\)/getLogger\(\'tornado\'\)/

I'd be totally fine with either patch. (GitHub still isn't letting me make pull requests, unfortunately.)

@bdarnell
Owner

I've just committed the change I described in my last message: No more root logger, and instead we use three new loggers, tornado.access, tornado.application, and tornado.general. I'm open to suggestions about the exact breakdown and naming.

https://github.com/facebook/tornado/blob/master/tornado/log.py

@bdarnell bdarnell closed this
@slingamn

Thanks, this looks wonderful. I like the breakdown.

@simpx

How I wish I could see this serval hours ago!

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Something went wrong with that request. Please try again.