0_NetworkLoggingWithPython.md

An example of Python logging over a network, starting with an example from https://docs.python.org/2/howto/logging-cookbook.html.

This is very handy if you have a rack of servers and you want to aggregate logging statements from one or several of them to in some convenient place. This is especially handy if you're using an inversion-of-control framework (my own work these days is with Buildbot, which relies upon Twisted), because a lot of what's happening may be obscured, for instance by Deferreds but also possibly by

Output from this thing currently looks like this, but I'm interested in the possibility of throwing log records in an SQL database for purposes of sorting/filtering/searching, and presenting them with something like http://datatables.net.

------
    6 localhost:root INFO
Jackdaws love my big sphinx of quartz.
------
    7 localhost:myapp.area1 DEBUG
Quick zephyrs blow, vexing daft Jim.
------
    7 localhost:myapp.area1 INFO
How quickly daft jumping zebras vex.
------
    7 localhost:myapp.area2 WARNING
Jail zesty vixen who grabbed pay from quack.
------
    7 localhost:myapp.area2 ERROR
The five boxing wizards jump quickly.
------
    7 localhost:myapp.area1 ERROR
ouch
Traceback (most recent call last):
  File "client.py", line 47, in <module>
    1 / 0
ZeroDivisionError: integer division or modulo by zero
------
    8 localhost:myapp.area2 INFO
  File "client.py", line 59, in <module>
    g()
  File "client.py", line 57, in g
    f()
  File "client.py", line 53, in f
    logger2.info(stack())

client.py

"""
https://docs.python.org/2/howto/logging-cookbook.html

Here is how LogRecords are pickled:
https://github.com/certik/python-2.7/blob/master/Lib/logging/handlers.py#L516

The server gets no control over the logging level. If you can live with that,
this is a very simple solution.
"""

import logging
import logging.handlers
import traceback

rootLogger = logging.getLogger()
rootLogger.setLevel(logging.DEBUG)
socketHandler = logging.handlers.SocketHandler(
    'localhost',
    logging.handlers.DEFAULT_TCP_LOGGING_PORT   # 9020
)
# don't bother with a formatter, since a socket handler sends the event as
# an unformatted pickle
rootLogger.addHandler(socketHandler)


def stack():
    stuff = traceback.format_stack()[:-1]
    stuff[-1] = stuff[-1].rstrip()
    return ''.join(stuff)


# Now, we can log to the root logger, or any other logger. First the root...
logging.info('Jackdaws love my big sphinx of quartz.')

# Now, define a couple of other loggers which might represent areas in your
# application:

logger1 = logging.getLogger('myapp.area1')
logger2 = logging.getLogger('myapp.area2')

logger1.debug('Quick zephyrs blow, vexing daft Jim.')
logger1.info('How quickly daft jumping zebras vex.')
logger2.warning('Jail zesty vixen who grabbed pay from quack.')
logger2.error('The five boxing wizards jump quickly.')

try:
    1 / 0
except ZeroDivisionError:
    logger1.exception('ouch')


def f():
    logger2.info(stack())


def g():
    f()

g()

database_stuff.py

# This is what to do if you want to store log records in a PostgreSQL database. MySQL should be fairly similar.
# This stuff gets added to server.py.
import contextlib
import psycopg2
from datetime import datetime


@contextlib.contextmanager
def conn_cursor():
    with contextlib.closing(
        psycopg2.connect(database="mylogdb", host="localhost", user="postgres", password="postgres")
    ) as conn:
        with contextlib.closing(conn.cursor()) as cursor:
            try:
                yield (conn, cursor)
                conn.commit()
            except:
                conn.rollback()
                raise
            finally:
                conn.close()


# This next piece is what would go into the handleLogRecord method.
        with conn_cursor() as (conn, cursor):
            created = datetime.fromtimestamp(record.created)
            cursor.execute(
                "INSERT INTO log_records (created, clientname, name, levelname, " +
                "pathname, lineno, funcname, msg) VALUES (%s, %s, %s, %s, %s, %s, %s, %s)",
                (
                    created,
                    record.clientname,
                    name,
                    record.levelname,
                    record.pathname,
                    int(record.lineno),
                    record.funcName,
                    record.msg
                )
            )

server.py

import pickle
import logging
import logging.handlers
import socket
import SocketServer
import struct


class LogRecordStreamHandler(SocketServer.StreamRequestHandler):
    """Handler for a streaming logging request.

    This basically logs the record using whatever logging policy is
    configured locally.
    """

    def handle(self):
        """
        Handle multiple requests - each expected to be a 4-byte length,
        followed by the LogRecord in pickle format. Logs the record
        according to whatever policy is configured locally.
        """
        while True:
            chunk = self.connection.recv(4)
            if len(chunk) < 4:
                break
            slen = struct.unpack('>L', chunk)[0]
            chunk = self.connection.recv(slen)
            while len(chunk) < slen:
                chunk = chunk + self.connection.recv(slen - len(chunk))
            obj = pickle.loads(chunk)
            record = logging.makeLogRecord(obj)
            client_ip, _ = self.connection.getpeername()
            record.clientname = socket.gethostbyaddr(client_ip)[0]
            self.handleLogRecord(record)

    def handleLogRecord(self, record):
        # if a name is specified, we use the named logger rather than the one
        # implied by the record.
        if self.server.logname is not None:
            name = self.server.logname
        else:
            name = record.name
        # If you're going to store records in a database, do that here.
        logger = logging.getLogger(name)
        # N.B. EVERY record gets logged. This is because Logger.handle
        # is normally called AFTER logger-level filtering. If you want
        # to do filtering, do it at the client end to save wasting
        # cycles and network bandwidth!
        logger.handle(record)


class LogRecordSocketReceiver(SocketServer.ThreadingTCPServer):
    """
    Simple TCP socket-based logging receiver suitable for testing.
    """

    allow_reuse_address = 1

    def __init__(self, host='localhost',
                 port=logging.handlers.DEFAULT_TCP_LOGGING_PORT,
                 handler=LogRecordStreamHandler):
        SocketServer.ThreadingTCPServer.__init__(self, (host, port), handler)
        self.abort = 0
        self.timeout = 1
        self.logname = None

    def serve_until_stopped(self):
        import select
        abort = 0
        while not abort:
            rd, _, _ = select.select([self.socket.fileno()],
                                     [], [],
                                     self.timeout)
            if rd:
                self.handle_request()
            abort = self.abort


def main():
    # logging.basicConfig(
    #     format='------\n%(relativeCreated)5d %(clientname)s:' +
    #     '%(name)s %(levelname)s\n%(message)s'
    # )
    logging.basicConfig(
        format='%(levelname)s  %(filename)s:%(lineno)d  %(message)s',
        level=logging.DEBUG
    )
    tcpserver = LogRecordSocketReceiver()
    try:
        tcpserver.serve_forever()
    except KeyboardInterrupt:
        pass
    tcpserver.server_close()

if __name__ == '__main__':
    main()