#################
Logging Messages
#################

.. currentmodule:: twiggy

This part describes how user code can log messages with twiggy.

To get started quickly, use :func:`quickSetup`.::

    >>> import twiggy
    >>> twiggy.quickSetup()

.. seealso:: Full details on :doc:`configuration`.

****************
The Magic log
****************

The main interface is the the magic :data:`log`.

.. doctest:: magic-log

    >>> from twiggy import log
    >>> log
    <twiggy.logger.Logger object at 0x...>

It works out of the box, using typical :mod:`.levels`. Arbitrary levels are *not* supported. Note that when logging, you never need to refer to any level object; just use the methods on the log.

.. doctest:: magic-log

    >>> log.debug('You may not care')
    DEBUG:You may not care
    >>> log.error('OMFG! Pants on fire!')
    ERROR:OMFG! Pants on fire!

The log can handle messages in several styles of :ref:`format strings<alternate-styles>`, defaulting to `new-style <http://docs.python.org/library/string.html#format-string-syntax>`_.

.. doctest:: magic-log

    >>> log.info('I wear {0} on my {where}', 'pants', where='legs')
    INFO:I wear pants on my legs

You can name your loggers.

.. doctest:: magic-log

    >>> mylog = log.name('alfredo')
    >>> mylog.debug('hello')
    DEBUG:alfredo:hello

.. _better-output:

**************
Better output
**************
Twiggy's default output strives to be user-friendly and to avoid pet peeves.

Newlines are suppressed by default; that can be turned off per-message.

.. doctest:: better-output

    >>> log.info('user\ninput\nannoys\nus')
    INFO:user\ninput\nannoys\nus
    >>> log.options(suppress_newlines=False).info('we\ndeal')
    INFO:we
    deal

Exceptions are prefixed by ``TRACE``. By default, :meth:`tracing <.trace>` will use the current exception, but you can also pass an exc_info tuple.

.. doctest:: better-output

    >>> try:
    ...     1/0
    ... except:
    ...     log.trace('error').warning('oh noes')
    WARNING:oh noes
    TRACE Traceback (most recent call last):
    TRACE   File "<doctest better-output[...]>", line 2, in <module>
    TRACE ZeroDivisionError: integer division or modulo by zero

.. seealso:: :ref:`How to fold exceptions to a single line<folding-exceptions>`

.. _structured-logging:

**********************
Structured Logging
**********************
I like this method chaining style a lot.

.. doctest:: structured-logging

    >>> log.name('benito').info('hi there')
    INFO:benito:hi there

It makes :term:`structured logging` easy. In the past, fielded data was stuffed in the text of your message:

.. doctest:: structured-logging

    >>> log.info('Going for a walk. path: {0} roads: {1}', "less traveled", 42)
    INFO:Going for a walk. path: less traveled roads: 42

Instead, you can use :meth:`.fields` to add arbitrary key-value pairs.  Output is easily parseable.

.. doctest:: structured-logging

    >>> log.fields(path="less traveled", roads=42).info('Going for a walk')
    INFO:path=less traveled:roads=42:Going for a walk

The :meth:`.struct` is a short cut for *only* logging fields. This is great for runtime statistics gathering.

.. doctest:: structured-logging

    >>> log.struct(paths=42, dolphins='thankful')
    INFO:dolphins=thankful:paths=42:

****************************
Partial Binding
****************************

Each call to :meth:`.fields` or :meth:`.options` creates a new, independent log instance that inherits all of the data of the parent.  This incremental binding can be useful for webapps.

.. doctest:: partial-binding

    >>> ## an application-level log
    ... webapp_log = log.name("myblog")
    >>> ## a log for the individual request
    ... current_request_log = webapp_log.fields(request_id='12345')
    >>> current_request_log.fields(rows=100, user='frank').info('frobnicating database')
    INFO:myblog:request_id=12345:rows=100:user=frank:frobnicating database
    >>> current_request_log.fields(bytes=5678).info('sending page over tubes')
    INFO:myblog:bytes=5678:request_id=12345:sending page over tubes
    >>> ## a log for a different request
    ... another_log = webapp_log.fields(request_id='67890')
    >>> another_log.debug('Client connected')
    DEBUG:myblog:request_id=67890:Client connected

Chained style is awesome. It allows you to create complex yet parsable log messages in a concise way.

.. doctest:: partial-binding

    >>> log.name('donjuan').fields(pants='sexy').info("hello, {who} want to {what}?", who='ladies', what='dance')
    INFO:donjuan:pants=sexy:hello, ladies want to dance?

*************************
Sample Output
*************************

.. _sample-file-output:

Routed to a `file <.FileOutput>`, the above produces the following::

    2010-03-28T14:23:34Z:DEBUG:You may not care
    2010-03-28T14:23:34Z:ERROR:OMFG! Pants on fire!
    2010-03-28T14:23:34Z:INFO:I like bikes
    2010-03-28T14:23:34Z:INFO:I wear pants on my legs
    2010-03-28T14:23:34Z:DEBUG:alfredo:hello
    2010-03-28T14:23:34Z:INFO:user\ninput\nannoys\nus
    2010-03-28T14:23:34Z:INFO:we
    deal
    2010-03-28T14:23:34Z:WARNING:oh noes
    TRACE Traceback (most recent call last):
    TRACE   File "<doctest better-output[...]>", line 35, in <module>
    TRACE ZeroDivisionError: integer division or modulo by zero
    2010-03-28T14:23:34Z:INFO:benito:hi there
    2010-03-28T14:23:34Z:INFO:Going for a walk. path: less traveled roads: 42
    2010-03-28T14:23:34Z:INFO:path=less traveled:roads=42:Going for a walk
    2010-03-28T14:23:34Z:INFO:dolphins=thankful:paths=42:
    2010-03-28T14:23:34Z:INFO:myblog:request_id=12345:rows=100:user=frank:frobnicating database
    2010-03-28T14:23:34Z:INFO:myblog:bytes=5678:request_id=12345:sending page over tubes
    2010-03-28T14:23:34Z:INFO:myblog:request_id=67890:Client connected
    2010-03-28T14:23:34Z:INFO:donjuan:pants=sexy:hello, ladies want to dance?
    2010-03-28T14:23:34Z:INFO:myblog:request_id=12345:rows=100:user=frank:frobnicating database
    2010-03-28T14:23:34Z:INFO:myblog:bytes=5678:request_id=12345:sending page over tubes
    2010-03-28T14:23:34Z:DEBUG:myblog:request_id=67890:Client connected