Welcome | Get started | Dive | Contribute | Topics | Reference | Changes | More

About logging

This document explains additional information about logging for developers. We assume that you have read About logging in the Hoster’s Guide.

Overview

Lino’s default logging messages go only to the console and (when an error occurs) to the ADMIN_EMAILS.

When you create a log directory in your project directory, Lino will additionally log to a file lino.log in that directory.

On a production site you probably want to also run a log server.

About logging in a development environment

On my development machine I have a runserver script that does:

set LINO_LOGLEVEL=DEBUG
python manage.py runserver

Logging SQL statements

The default logging level for the django.db.backends handler is WARNING. You can change this default value by setting the LINO_SQL_LOGLEVEL variable.

LINO_SQL_LOGLEVEL

The logging level to set for the django.db.backends handler instead of the default value WARNING.

The Lino logger

Side note: Code snippets (lines starting with >>>) in this document get tested as part of our development workflow. The following initialization snippet tells you which demo project is being used in this document.

>>> from lino import startup
>>> startup('lino_book.projects.noi1e.settings.demo')
>>> from lino.api.doctest import *

>>> from lino import logger
>>> logger.handlers
[<StreamHandler (INFO)>, <AdminEmailHandler (ERROR)>]
>>> logger.info("Hello, world!")
Hello, world!
>>> logger.debug("Foolish humans trying to understand me")

History-aware logging

When Lino is in history-aware logging mode, it logs a message Started %s (using %s) --> PID %s at process startup (and a message Done PID %s at termination).

This kind of messages are usually disturbing for development and testing, but they are interesting for the system administrator of a production site.

The history-aware logging mode is automatically set to True when a logger directory (log) exists in the project directory.

Testing the log directory

When a socket file exists (a file named lino.log.sock in the log directory), then Lino assumes that you have a log server running that is responsible for writing to the lino.log file.

We are going to play in the min1 demo project:

>>> from atelier.sheller import Sheller
>>> shell = Sheller('lino_book/projects/min1')

The demo sites have no log directory and hence no lino.log file.

>>> shell("ls log")
ls: cannot access 'log': No such file or directory

>>> shell("python manage.py prep --noinput")
... 
`initdb std demo demo2` started on database .../min1/default.db.
...
Installed 200 object(s) from 9 fixture(s)

For the following snippets we temporarily enable file logging in the min1 demo site by creating a log directory.

>>> shell("mkdir log")

>>> shell("python manage.py prep --noinput")
... 
Started manage.py prep --noinput (using lino_book.projects.min1.settings) --> PID ...
`initdb std demo demo2` started on database .../min1/default.db.
...
Done manage.py prep --noinput (PID ...)

>>> shell("ls log")
lino.log

>>> shell("cat log/lino.log")
... 
2... INFO [lino ...] : Started manage.py prep --noinput (using lino_book.projects.min1.settings) --> PID ...
2... INFO [lino ...] : `initdb std demo demo2` started on database .../min1/default.db.
2...
2... INFO [lino ...] : Done manage.py prep --noinput (PID ...)

When there is a log directory, the Lino logger will log to the lino.log file as well.

The following snippet demonstrates an edge case: we simulate a log server by creating a fake socket file.

>>> shell("rm log/lino.log")

>>> shell("touch log/lino.log.sock")

The process then sends log records to that socket, without asking whether the server actually runs:

>>> shell("python manage.py prep --noinput")
... 
Started manage.py prep --noinput (using lino_book.projects.min1.settings) --> PID ...
...

But since in our case no log server is actually running, the lino.log file has not been written (only the socket file is there):

>>> shell("ls log")
lino.log.sock

Tidy up and remove all traces:

>>> shell("rm log/lino.log.sock")

>>> shell("rmdir log")

Relation between logging level and verbosity

The relation between logging level and verbosity is not yet clear.

You can set LINO_LOGLEVEL to “WARNING” in order to get rid of quite some messages:

>>> import os
>>> env = dict()
>>> env.update(os.environ)
>>> env.update(LINO_LOGLEVEL="WARNING")
>>> shell("python manage.py prep --noinput", env=env)
... 
No changes detected
Operations to perform:
  Synchronize unmigrated apps: about, bootstrap3, contacts, countries, extjs, jinja, lino, office, printing, staticfiles, system, users, xl
  Apply all migrations: sessions
Synchronizing apps without migrations:
  Creating tables...
    Creating table system_siteconfig
    Creating table users_user
    Creating table users_authority
    Creating table countries_country
    Creating table countries_place
    Creating table contacts_partner
    Creating table contacts_person
    Creating table contacts_companytype
    Creating table contacts_company
    Creating table contacts_roletype
    Creating table contacts_role
    Running deferred SQL...
Running migrations:
  Applying sessions.0001_initial... OK
Installed 200 object(s) from 9 fixture(s)

Setting LINO_LOGLEVEL to “WARNING” does not remove messages issued by Django because Django does not use the logging system to print these messages. To get rid of these messages as well, you can set verbosity to 0:

>>> shell("python manage.py prep --noinput -v0", env=env)
... 

Site attributes related to logging

class lino.core.site.Site

log_each_action_request

Whether Lino should log every incoming request for non readonly actions.

This is experimental. Theoretically it is useless to ask Lino for logging every request since the web server does this. OTOH Lino can produce more readable logs.

There is no warranty that actually each request is being logged. It currently works only for requests that are being processed by the kernel’s run_action methods.

logger_filename

The name of Lino’s main log file, created in setup_logging().

Default value is lino.log.

logger_format

The format template to use for logging to the lino.log file.

auto_configure_logger_names = 'atelier lino'

A string with a space-separated list of logger names to be automatically configured. See setup_logging().

log_sock_path

The full Path of the logger socket file (if this process is logging to the log server, otherwise None).

setup_logging(self)

This is called during Site startup before any plugins are loaded because all this must happen before Django passes the setting to the logging.config.dictConfig function.

It does nothing if auto_configure_logger_names is empty.

It modifies the DEFAULT_LOGGING setting.

It is designed to work with the LOGGING and LOGGING_CONFIG settings unmodified.

It does the following modifications:

• Define a default logger configuration that is initially the same as the one used by Django:

  {
      'handlers': ['console', 'mail_admins'],
      'level': 'INFO',
  }
  

• If the site_dir has a subdirectory named log, and if logger_filename is not empty, add a handler named file and a formatter named verbose, and add that handler to the default logger configuration.

• Apply the default logger configuration to every logger name in auto_configure_logger_names.

• (does no longer) configure the console handler to write to stdout instead of Django’s default stderr (as explained here) because that breaks testing.

It does nothing at all if auto_configure_logger_names is set to None or empty.