cms-dev/cms — pull request #186 by lerks (2013-08-27 14:50:26+00:00)
Title: Use Python's logging system

**TL;DR** I wrote a new logger that uses Python's `logging`: go read the code!

Do you have some time? Read the full explanation on what was wrong and how (I think) I fixed it!

### What we had before

We had some oddities in the logging system. Mainly, two `Logger` classes were defined: one in `cms/__init__.py` and one in `cms/io/Utils.py`. The former was the one used by almost the entirety of CMS as it was the more "complete" one: it printed messages to stdout and, if properly initialized (with the coords of the service it was running on), it also stored them on disk (the path depended on the coords) and sent them to LogService (even if coords weren't necessary for this we did it only if they were given).

Services were initializing the logger as the first operation in their constructor (even before calling their parent's `__init__`) and were therefore using it at full potential. Other scripts (the ones in `cmscontrib`) were running it in "limited mode" (i.e. just stdout). The only code that had issues using this logger was the one in `cms.io`, as it would have caused circular imports. To solve this, `Service` allowed for a "custom logger" to be given as a constructor argument. If none was, it would fall back on the "simple" one defined in `cms/io/Utils.py` (which just printed to stdout). This is the why services initialized the logger so early: to allow errors in `Service.__init__` to be caught, stored and sent to LogService. All this required some ugly `global` assignments to be used. (I'm not even sure if the "dummy" logger was actually used somewhere in practice)

### What I did

In this commit I focused on replicating the exact same final "result" (same destinations, same formatting, etc.) that we had before, using Python's official `logging` library.

This library simplifies the design a lot. The decoupling of loggers and handlers allows all code that produces messages to just get a logger whenever they want (without fearing circular dependencies) and start logging (without worrying about where the messages will land). On the other hand, handlers can be installed when they are ready. A stdout handler is set up as soon as possible (i.e. by `cms/log.py`, which is imported by `cms/__init__.py`). The other handlers are installed if and when a service is initialized.

The hierarchical structure of loggers also helps: we install handlers on the root logger to get all messages that are produced, by us and by libraries we use (e.g. tornado, requests, etc.). But we send messages on loggers named as the module that fires them (e.g. `cms.grading.ScoreType`), as suggested by the `logging` manual. This allows easy filtering of messages based on their origin. Yet, actually, the module name is already accessible by other means and we could use more "semantically" meaningful names for loggers, like tornado does (it uses "access", "application" and "general" to distinguish between access logs, application errors and internal errors and allow to treat them separately). If someone has a proposal on how to do it please tell me: for now we'll stick with module names.

### What I did _not_

The only feature I didn't port yet is the "operation" attribute, because I consider it conceptually broken: we cannot alter the state of a global shared singleton instance that could be used simultaneously by code performing different operations, as these changes could interfere the one with the other. This didn't happen before, as async was blocking, but it could now that we use gevent.
Actually, it might still work as there are very few users of "operation" (Worker, ContestImporter, ContestExporter and SpoolExporter) and they already limit concurrency by other means. But I don't want to support a broken API and I therefore implemented other ways to give the operation (i.e. passing `extra={"operation":...}` or using an adapter to have it done automatically). If you're happy with that I'll proceed to port Worker and company to it.

### Minors

I removed all logging configuration options as I think we can autodetect color support instead of requiring manual settings.

### Future

Use different formatters for different handlers (e.g. don't show service coords in the per-service stdout and file output). Use the "official" RotatingFileHandler instead of doing it manually.