The log service

It’s often useful to log some information during the execution of a Web application to trace the execution of the requests and to provide useful information for debugging when something goes wrong. The most common use-case is to log the exceptions tracebacks to a file on the server that provide the context where the error occurred so that we can fix the problem without disclosing sensitive information to the end-users.

Python ships with a logging module that provides everything we need in a Web development context. However, it is relatively complex to configure and it’s configuration is a singleton, which is problematic in a multi-applications setup (that is, when the same nagare-admin serve process serves more than one application).

In order to solve these problems, Nagare provides its own nagare.log service , which is built on top of the logging module but greatly simplifies its usage and configuration for common use-cases.

Basic Usages

Using The default logger

By default, when you serve Web applications with the nagare-admin serve utility, Nagare creates a dedicated logger, handler and formatter for each application, and activates them: this is the purpose of the nagare.log.configure and nagare.log.activate functions.

You can use the module level functions of the log module to write messages to the default logger of the currently running application, as shown in the example below:

from nagare import presentation, log

class Root(object):
    pass

@presentation.render_for(Root)
def render(self, h, *args):
    log.info('Rendering the Root component')
    # some rendering code...
    return h.root

app = Root

Then, each time the default view of the Root component is rendered, this line should appear in the console shell (which is the output of the default logger):

2012-06-14 10:22:38,379 - nagare.application.myapp - INFO - Rendering the root component

As you see, the messages are issued in the nagare.application.myapp namespace, which is the namespace of the messages coming from the Nagare application called myapp.

Here is the full listing of the module-level functions of the nagare.log module:

Function	Effect
log.debug(msg, *args, **kw)	Logs a message with DEBUG level on the application logger
log.info(msg, *args, **kw)	Logs a message with INFO level on the application logger
log.warning(msg, *args, **kw)	Logs a message with WARNING level on the application logger
log.error(msg, *args, **kw)	Logs a message with ERROR level on the application logger
log.critical(msg, *args, **kw)	Logs a message with CRITICAL level on the application logger
log.exception(msg, *args, **kw)	Logs a message with ERROR level on the application logger, and also logs the current exception information
log.log(level, msg, *args, **kw)	Logs a message with the specified level on the application logger

All these functions accept variable arguments and keyword arguments, which are documented in the logging module, here.

Overriding the default configuration

The [[logger]], [[hander]] and [[formatter]] sub-sections of the [logging] section in the application configuration file are dedicated to configure the default application logger.

The default logging setup is equivalent to the following [logging] section, where <name> is replaced by the name of the application (please refer to the logging’s module configuration file format for a better understanding of the configuration of loggers, handlers and formatters):

[logging]

[[logger]]
qualname=nagare.application.<name>
level=INFO
propagate=1

[[handler]]
class=StreamHandler
args=(sys.stderr,)

[[formatter]]
format=%(asctime)s - %(name)s - %(levelname)s - %(message)s

As you can see, by default, the log messages with a level greater or equal to INFO are printed to sys.stderr via a StreamHandler.

It’s possible to override this default logging configuration by adding your own [logging] section to the application configuration file. Here, the logging level of the application is set to DEBUG:

[logging]
[[logger]]
level=DEBUG

Here, a new handler is defined to log the messages to the file /tmp/myapp.log. We use a RotatingFileHandler instead of the classical FileHandler since we want the file to be log-rotated in order to prevent it from becoming too large:

[logging]
[[handler]]
class=handlers.RotatingFileHandler
args="('/tmp/myapp.log', 'a', 10485760, 10, 'UTF-8')"

Using the Nagare IDE

When the Nagare IDE is launched at the same time than your application (i.e nagare-admin serve <name> ide), a second handler is bound to the default logger so that all the messages are also sent to the IDE log panel.

Advanced Usages

Creating other application loggers

As seen above, Nagare makes it easy to log messages in an application. However, as your application becomes more complex and is broken down in several modules and packages, it may become hard to track down where you sent a particular message or to analyze the log file which is now filled with numerous log messages.

In this situation, it’s generally useful to organize the log messages into namespaces, so that we can enable/disable the logging of messages in some namespaces or send messages with different namespaces to different handlers.

For this purpose, Nagare offers a log.get_logger(namespace) function that creates a logger which puts the messages into the specified namespace. To create a new logger for your application, use a relative name starting with a dot. In this case, the new namespace is relative to the application namespace, e.g. nagare.application.myapp.

The logger object offers the same functions as the log module for writing messages, that is logger.debug, logger.info, logger.warning, logger.error, logger.critical, logger.exception and logger.log, with the same parameters.

In this example, we will log all the messages generated in the views to a specific nagare.application.myapp.ui namespace:

from nagare import log

@presentation.render_for(Root)
def render(self, h, *args):
    log.get_logger('.ui').debug('Rendering the Root component')
    # some rendering code...
    return h.root

and you can see, the message is now attached to the nagare.application.myapp.myapp.ui namespace:

2012-06-14 10:22:38,379 - nagare.application.myapp.ui - INFO - Rendering the root component

Being under the nagare.application.myapp namespace, this logger propagates the messages to the default logger. Also this logger inherits the default logger configuration, which can be overridden:

[[logging]]
[loggers]
keys=ui   # Declare the new logger

[[logger_ui]]
qualname=.ui    # Relative namespace
level=CRITICAL
# No specific handler: propagate the messages to the default application logger
handlers=

Here the log level of the logger is set to CRITICAL.

Or a more complex configuration can be created, for example to log the messages to a specific log file:

[logging]
[[loggers]]
keys=ui   # Declare the new logger

[[handlers]]
keys=logfile   # Declare the new handler

[[formatters]]
keys=simple   # Declare the new formatter

[[logger_ui]]
qualname=.ui    # Relative namespace
handlers=logfile
propagate=0   # Don't propagate the messages to the default application logger

[[handler_logfile]]
class=handlers.RotatingFileHandler
args="('/tmp/myapp_ui.log', 'a', 10485760, 10, 'UTF-8')"  # Specific log file
formatter=simple

[[formatter_simple]]
format=%(levelname)s: %(message)s

Creating other loggers

Any other general loggers can be created the same way, by just giving a full absolute namespace.

For example the SQLAlchemy documentation states the name of the SQL query logger is sqlalchemy.engine. So this logging configuration will display all the generated SQL queries:

[logging]
[[loggers]]
keys=sa

[[handlers]]
keys=stderr

[[formatters]]
keys=multilines

[[logger_sa]]
qualname=sqlalchemy.engine   # The absolute SQLAlchemy logger namespace
level=INFO
handlers=stderr

[[handler_stderr]]
class=StreamHandler
args=(sys.stderr,)
formatter=multilines

[[formatter_multilines]]
format={ %(message)s }