Opened 14 years ago

Closed 13 years ago

Last modified 12 years ago

#12012 closed (fixed)

Integration with the Python standard library logging module

Reported by: simon Owned by: nobody
Component: Core (Other) Version: dev
Severity: Keywords:
Cc: Maniac@…, rob@…, remco@…, cstejerean@…, medoslav@…, gciotta@…, remibroemeling, Alexander Koshelev, tomvons@… Triage Stage: Accepted
Has patch: yes Needs documentation: no
Needs tests: no Patch needs improvement: no
Easy pickings: no UI/UX: no

Description

Tracking ticket for work to integrate Python's logging module in to Django, providing logging hooks at various points in the framework as well as a Django-style interface for enabling / disabling / configuring logging. See also LoggingProposal.

Attachments (8)

12012-r11603.diff (8.1 KB ) - added by simon 14 years ago.
12012-r11620.diff (1.5 KB ) - added by Vinay Sajip 14 years ago.
Patch to show how both logging and class_prepared listening can be done via setting.py
12012-r11624.diff (1.9 KB ) - added by Vinay Sajip 14 years ago.
Improved patch to show hooks at settings read, pre app/model load and post app/model load
settings.py (4.6 KB ) - added by Vinay Sajip 14 years ago.
Improved settings.py for use with patch in 12012-r11624.diff
logging.patch (4.1 KB ) - added by djinn 14 years ago.
logging changes for basehttp server
t12012-alpha1.diff (43.3 KB ) - added by Russell Keith-Magee 13 years ago.
First draft of logging patch for trunk
t12012-rc1.diff (62.0 KB ) - added by Russell Keith-Magee 13 years ago.
RC1 of logging patch
t12012-rc2.diff (61.8 KB ) - added by Russell Keith-Magee 13 years ago.
RC2 of logging patch.

Download all attachments as: .zip

Change History (35)

by simon, 14 years ago

Attachment: 12012-r11603.diff added

comment:1 by simon, 14 years ago

Has patch: set
Needs documentation: set
Needs tests: set
Patch needs improvement: set

comment:2 by Vinay Sajip, 14 years ago

Comments on 12012-r11603.diff:

Re. the change in conf/__init__.py:

I know there's an open issue about where to place setup code in Django to run once only, so I assume this placement of the logging configuration code is just temporary because no better mechanism exists? As a user, I would prefer to control exactly when and how logging gets set up, and not to have it done automagically for me. If you feel that automagic configuration is wanted by the majority of users, you can still have an additional setting called e.g. AUTOLOG, set by default to True if you want, which does the logging setup automatically when true but can be overridden when more precise control is wanted. In fact if more granularity over logging settings is wanted, you could have a settings dict LOGGING_CONFIG { "enabled": True, "automatic": True } etc.

Re. the change in db/backends/__init__.py:

You might want to control via settings.py whether a CursorLoggingWrapper is returned rather than a plain cursor. There might be some petrol-heads for whom speed is paramount ;-)

Re. the change in "/dev/null", presumably this is your new django.utils.log:

I've proposed on python-dev a change to Python logging to add a dictConfig() function to the logging.config module. The start of the thread is here (though some of the posts don't appear in this thread because of broken email clients) and the draft of the schema I'm proposing is here. It would be good if we could align the schemata for the LOGGING dict.

comment:3 by simon, 14 years ago

I might be going about the initialisation the wrong way then. Here's what I want to achieve: without the user needing to do anything at all (including modifying a settings.py created before logging was added to Django) I want ALL messages to any logger beneath "django" to be silently swallowed, no matter what the severity. My understanding is that the correct way to do this is to hook up a NullHandler and set "propogate = False" on the "django" logger as early as possible. Is there a better way of achieving that?

comment:4 by Vinay Sajip, 14 years ago

No, you're right about the best way to achieve what you want - i.e. by adding the NullHandler and setting propagate to False on the "django" logger, you will indeed ensure that any thing logged to "django.*" will disappear into the ether. That'll be fine from a backward compatibility point of view - users who have old settings files shouldn't see any unexpected logging messages.

The other question is what different modes of initialisation of logging might be wanted by different users. If a user wants Django to automatically configure logging for them, they can define a dict bound to LOGGING in settings.py. This covers the simplest use case - users don't need to do anything else. About the schema for the dict, it would be nice if we could align the schema with what I'm proposing on python-dev, linked-to above (the schema is different to what Ivan Sagalaev suggested on the django-developers thread, but then it has to cover functionality of the logging module such as shared handlers, filters, formatters etc. which wasn't covered by Ivan's overview, but will be needed in certain cases).

In a more complex use case, say the user wants to set up logging using their own code, but this needs to be done as early as possible and be called just once. For this, I suggested a callback mechanism here on your thread about "Best place for code that processes stuff from settings.py once". There, the user could define callbacks for logging or anything else which needs to be done just once. Their logging setup callback can use any mechanism to configure logging, e.g. programmatically using the logging getLogger/addHandler APIs or via loading a dict from YAML or JSON or just invoking the dict config mechanism using a dict obtained from some other source - including a literal dict in settings.py not called LOGGING ;-)

One more point about handlers. Because propagate is set to False for the "django" logger, in order for users to see django events, they will explicitly have to add appropriate handlers to the "django" logger. These can be the same handlers as they e.g. attach to the root logger, or completely different handlers.

A fairly common usage pattern is to attach console, file handlers to the root logger and nowhere else (but that wouldn't work for Django events, as I've explained above). Another common pattern is to attach console and file handlers to the root, and additional handlers (e.g. SMTP or file handlers pointing to files which just store errors) for particular severities (e.g. ERROR or CRITICAL) and/or particular areas of the application.

Of course, knowledgeable users can, if they wish, set the "django" logger's propagate flag to True in their logging setup code, which means that they then don't need to attach handlers specifically to the "django" logger, as events will propagate up to the root logger.

comment:5 by Ivan Sagalaev, 14 years ago

Cc: Maniac@… added

by Vinay Sajip, 14 years ago

Attachment: 12012-r11620.diff added

Patch to show how both logging and class_prepared listening can be done via setting.py

by Vinay Sajip, 14 years ago

Attachment: 12012-r11624.diff added

Improved patch to show hooks at settings read, pre app/model load and post app/model load

by Vinay Sajip, 14 years ago

Attachment: settings.py added

Improved settings.py for use with patch in 12012-r11624.diff

comment:7 by Vinay Sajip, 14 years ago

Result of running ./manage.py validate with patch in 12012-r11624.diff and attached settings.py:

2009-10-15 14:58:31,772 INFO     logtest       Adding listener for class_prepared...
2009-10-15 14:58:31,803 INFO     logtest       class_prepared listener called: ContentType
2009-10-15 14:58:31,805 INFO     logtest       class_prepared listener called: Permission
2009-10-15 14:58:31,807 INFO     logtest       class_prepared listener called: Group
2009-10-15 14:58:31,810 INFO     logtest       class_prepared listener called: User
2009-10-15 14:58:31,813 INFO     logtest       class_prepared listener called: Message
2009-10-15 14:58:31,843 INFO     logtest       class_prepared listener called: Session
2009-10-15 14:58:31,864 INFO     logtest       class_prepared listener called: Site
2009-10-15 14:58:31,916 INFO     logtest       ORM works: all users: vinay (Vinay Sajip)

comment:8 by Vinay Sajip, 14 years ago

I've proposed the detail of a dictionary schema for Python logging configuration on python-dev in this post. An example configuration in YAML format would be:

formatters:
  brief:
	format: '%(levelname)-8s: %(name)-15s: %(message)s'
  precise:
	format: '%(asctime)s %(name)-15s %(levelname)-8s %(message)s'
        datefmt: '%Y-%m-%d %H:%M:%S'
filters:
  allow_foo:
	name: foo
handlers:
  console:
	class : logging.StreamHandler
	formatter: brief
	level   : INFO
	stream  : ext://sys.stdout
	filters: [allow_foo]
  file:
	class : logging.handlers.RotatingFileHandler
	formatter: precise
	filename: logconfig.log
	maxBytes: 1024
	backupCount: 3
  debugfile:
	class : logging.FileHandler
	formatter: precise
	filename: logconfig-detail.log
	mode: a
  email:
	class: logging.handlers.SMTPHandler
	mailhost: localhost
	fromaddr: my_app at domain.tld
	toaddrs:
	  - support_team at domain.tld
	  - dev_team at domain.tld
	subject: Houston, we have a problem.
loggers:
  foo:
	level : ERROR
	handlers: [debugfile]
  spam:
	level : CRITICAL
	handlers: [debugfile]
	propagate: no
  bar.baz:
	level: WARNING
root:
  level     : DEBUG
  handlers  : [console, file]

comment:9 by Rob Hudson, 14 years ago

Cc: rob@… added

comment:10 by Remco Wendt, 14 years ago

Cc: remco@… added

comment:11 by anonymous, 14 years ago

See Simon's experimental branch on this feature on github and this djd thread

comment:12 by offbytwo, 14 years ago

Cc: cstejerean@… added

comment:13 by anonymous, 14 years ago

Cc: medoslav@… added

comment:14 by Russell Keith-Magee, 14 years ago

Triage Stage: UnreviewedAccepted

comment:15 by gciotta, 14 years ago

Cc: gciotta@… added

comment:16 by vinay_sajip@…, 14 years ago

milestone: 1.3

I've added a Launchpad branch which is an up-to-date branch of Django trunk (as at today - 13 May 2010), with updated logging functionality (including a copy of dictConfig, from my project of the same name which is a standalone version of the new PEP 391 logging configuration functionality, usable with Python 2.4, 2.5 and 2.6). I've inserted some logging statements in app loading, SQL execution and request handling (including handling of uncaught and other exceptions).

There's also an example project which uses the Django logging API to configure logging in settings.py, via PEP 391-compatible configuration dictionary (the initialisation code is only called once, even though settings.py is imported at least twice).

Bazaar branch for the version of Django with logging enabled: https://code.launchpad.net/~vinay-sajip/django/logging
Bazaar branch for test project, which shows how logging can be configured: https://code.launchpad.net/~vinay-sajip/+junk/django-logtest

The test app is set up to log to /tmp/logtest.log (which isn't spammed with SQL logging) and /tmp/logtest-sql.log (which contains the SQL statements executed).

Basic diffs to show what was added:

http://bazaar.launchpad.net/~vinay-sajip/django/logging/revision/53 - Added callback hooks
http://bazaar.launchpad.net/~vinay-sajip/django/logging/revision/55 - Added log module reference
http://bazaar.launchpad.net/~vinay-sajip/django/logging/revision/56 - Added log module itself
http://bazaar.launchpad.net/~vinay-sajip/django/logging/revision/55 - Removed log module reference (as not needed)
http://bazaar.launchpad.net/~vinay-sajip/django/logging/revision/61 - Added dictconfig.py and changed code to use it
http://bazaar.launchpad.net/~vinay-sajip/django/logging/revision/62 - Added useful default to configuration
http://bazaar.launchpad.net/~vinay-sajip/django/logging/revision/63 - Added logging to app loading
http://bazaar.launchpad.net/~vinay-sajip/django/logging/revision/65 - Added logging for SQL and uncaught exceptions in request handling
http://bazaar.launchpad.net/~vinay-sajip/django/logging/revision/67 - Added some more logging to request handling code

Your feedback will be appreciated, especially in terms of other parts of Django that you think would benefit particularly from having logging added.

by djinn, 14 years ago

Attachment: logging.patch added

logging changes for basehttp server

comment:17 by remibroemeling, 14 years ago

Cc: remibroemeling added

comment:18 by remibroemeling, 14 years ago

A comment on http://bazaar.launchpad.net/~vinay-sajip/django/logging/revision/56 , specifically the code:

if len(logger.handlers) == 0:
    logger.addHandler(NullHandler())
logger.propagate = False

This will set the 'django' logger not to propagate, even if the user (previous to the inclusion of django) has it configured TO propagate. Changing it to:

if len(logger.handlers) == 0:
    logger.addHandler(NullHandler())
    logger.propagate = False

... would have the same effect in the case of Django starting up when logging hasn't been configured, but wouldn't alter an existing logging setup in a way that the user wouldn't expect.

comment:19 by remibroemeling, 14 years ago

Sorry for the double post, but possibly the .setLevel() call should be moved to take place under "if len(logger.handlers) == 0:" as well.

comment:20 by Vinay Sajip, 14 years ago

Updated code on Launchpad to bring up to date with Django trunk (r13679) and to deal with points raised by Remi Broemeling. See

http://bazaar.launchpad.net/~vinay-sajip/django/logging/

for the latest version.

by Russell Keith-Magee, 13 years ago

Attachment: t12012-alpha1.diff added

First draft of logging patch for trunk

comment:21 by Alexander Koshelev, 13 years ago

Cc: Alexander Koshelev added

by Russell Keith-Magee, 13 years ago

Attachment: t12012-rc1.diff added

RC1 of logging patch

comment:22 by anonymous, 13 years ago

I've made a working logger by just using a simple encapsulation of database table with two main field: level and text, this has the advantage of being instantly available in Django admin. What am I missing with this approach?

comment:23 by Russell Keith-Magee, 13 years ago

Needs documentation: unset
Needs tests: unset
Patch needs improvement: unset

@anon - Nothing in particular; if you want to log to database, that's certainly an option with an appropriate handler.

My only concern would be the extra database load that this logging technique would introduce, but that isn't something that you can declare as universally bad; it entirely depends on your load pattern and the amount of logging you intend to do.

comment:24 by Tom von Schwerdtner, 13 years ago

Cc: tomvons@… added

by Russell Keith-Magee, 13 years ago

Attachment: t12012-rc2.diff added

RC2 of logging patch.

comment:25 by Russell Keith-Magee, 13 years ago

Resolution: fixed
Status: newclosed

(In [13981]) Fixed #12012 -- Added support for logging. Thanks to Vinay Sajip for his draft patch, and to the many people who gave feedback during development of the patch.

comment:26 by Marti Raudsepp, 13 years ago

@anonymous: Did you consider database transactions?

If you're using database transactions in your app, the logging will seem to be working fine, until you actually reach an error... The errors will be successfully written out to your log table, but then comes along your transaction manager and rolls everything back due to the failed transaction. ;)

comment:27 by Jacob, 12 years ago

milestone: 1.3

Milestone 1.3 deleted

Note: See TracTickets for help on using tickets.
Back to Top