Socket server TCP multi-thread - logger

Ampliando el código de la entrada anterior vamos a extender la funcionalidad del socket server.
Como ya vimos en la entrada previa, construíamos la lógica del socket server extendiendo varias clases del módulo SocketServer y sobrescribiendo métodos según el diagrama siguiente:

En este caso, apoyándonos en la misma estructura de clases y métodos vamos a ampliar la funcionalidad guardando en un fichero de logs lo recibido a través del socket server, estableciendo además un límite máximo de clientes simultáneos a los que el socket server atenderá.

Vayamos paso a paso.

Logs:
Emplearemos el módulo logging el cual nos va a facilitar el trabajo.
Los parámetros principales parámetros que debemos indicar son el directorio donde almacenarlos y el nombre del fichero. Aprovechando la potencia del módulo vamos a hacer que los el fichero de logs rote de forma automática cada noche y manteniendo un máximo número de ficheros, de forma que el propio módulo borre aquellos más antiguos de x días.
De este modo tendremos los siguientes parámetros en nuestro código:

LOG_FOLDER = '/var/log/socket-server/'
LOG_FILE = 'socket-server.log'
ROTATE_TIME = 'midnight'
LOG_COUNT = 10

Con los parámetros anteriores ya podemos "armar" nuestro logs:

import os
import logging, logging.handlers

log_folder = os.path.dirname(LOG_FOLDER)

if not os.path.exists(log_folder):
 try:
  os.makedirs(log_folder)
 except Exception as error:
  print 'Error creating the log folder: %s' % error

try:
 logger = logging.getLogger('socket-server')
 loggerHandler = logging.handlers.TimedRotatingFileHandler(LOG_FOLDER + LOG_FILE , ROTATE_TIME, 1, backupCount=LOG_COUNT)
 formatter = logging.Formatter('%(asctime)s %(levelname)s %(message)s')
 loggerHandler.setFormatter(formatter)
 logger.addHandler(loggerHandler)
 logger.setLevel(logging.DEBUG)
except:
 print '------------------------------------------------------------------'
 print '[ERROR] Error writing log at %s' % INTERNAL_LOG
 print '[ERROR] Please verify path folder exits and write permissions'
 print '------------------------------------------------------------------'
 exit() 

Lo que hacemos con el código anterior es comprobar si el directorio existe y en caso de no existir lo intentamos crear, trazando cualquier error que pudiera producirse al crearlo.
Por ejemplo, en sistemas unix, si el usuario que ejecuta el código no tiene permiso de escritura sobre el directorio que contendrá al directorio de logs obtendremos un error como el siguiente:

Error creating the log folder: [Errno 13] Permission denied: '/var/log/socket-server'

Por ello debemos asegurarnos que corremos el código con usuario con permisos suficientes.
El resto del código aportan la lógica comentada antes de rotación, número de ficheros de logs, etc..

Veamos a continuación como incluirlo en el código del socket server incluyendo además el límite de hilos máximos en ejecución o dicho de otro modo el número de clientes simultáneos que queremos atender:

#!/usr/bin/env python

import threading
import SocketServer, socket
import sys
import os
import logging, logging.handlers

TIMEOUT = 10
HOST = '0.0.0.0'
PORT = 3456

MAX_THREADS = 50

LOG_FOLDER = '/var/log/socket-server/'
LOG_FILE = 'socket-server.log'
ROTATE_TIME = 'midnight'
LOG_COUNT = 10

log_folder = os.path.dirname(LOG_FOLDER)

if not os.path.exists(log_folder):
 try:
  os.makedirs(log_folder)
 except Exception as error:
  print 'Error creating the log folder: %s' % error
        exit()

try:
 logger = logging.getLogger('socket-server')
 loggerHandler = logging.handlers.TimedRotatingFileHandler(LOG_FOLDER + LOG_FILE , ROTATE_TIME, 1, backupCount=LOG_COUNT)
 formatter = logging.Formatter('%(asctime)s %(levelname)s %(message)s')
 loggerHandler.setFormatter(formatter)
 logger.addHandler(loggerHandler)
 logger.setLevel(logging.DEBUG)
except Exception as error:
 print '------------------------------------------------------------------'
 print '[ERROR] Error writing log at %s: %s' % (LOG_FOLDER, error)
 print '[ERROR] Please verify path folder exits and write permissions'
 print '------------------------------------------------------------------'
 exit()


class RequestHandler(SocketServer.BaseRequestHandler):
    def handle(self):
        try:
            # chequeamos el numero de threads activos. Si es mayor que el limite establecido cerramos la conexion y no atendemos al cliente. Lo trazamos
            if threading.activeCount() > MAX_THREADS:
                logger.warn('%s -- Execution threads number: %d', threading.currentThread().getName(),
                            threading.activeCount() - 1)
                logger.warn('Max threads number as been reached.')
                self.closed()
            # si no hemos alcanzado el limite lo atendemos
            else:
                threadName = threading.currentThread().getName()
                activeThreads = threading.activeCount() - 1
                clientIP = self.client_address[0]
                logger.info('[%s] -- New connection from %s -- Active threads: %d' , threadName, clientIP, activeThreads)
                data = self.request.recv(1024)
                logger.info('[%s] -- %s -- Received: %s' , threadName, clientIP, data)
                response = 'Thanks %s, message received!!' % clientIP
                self.request.send(response)
        except Exception, error:
            if str(error) == "timed out":
                logger.error ('[%s] -- %s -- Timeout on data transmission ocurred after %d seconds.' ,threadName, clientIP, TIMEOUT)

class ThreadedTCPServer(SocketServer.ThreadingMixIn, SocketServer.TCPServer):
    def server_bind(self):
        self.socket.setsockopt(socket.SOL_SOCKET, socket.SO_REUSEADDR, 1)
        self.socket.bind(self.server_address)

    def finish_request(self, request, client_address):
        request.settimeout(TIMEOUT)
        SocketServer.TCPServer.finish_request(self, request, client_address)
        SocketServer.TCPServer.close_request(self, request)

try:
    print "Starting server TCP at IP %s and port %d..." % (HOST,PORT)
    server = ThreadedTCPServer((HOST, PORT), RequestHandler)
    server.serve_forever()
except KeyboardInterrupt:
    server.socket.close()

Las etiquetas empleadas son bastante descriptivas:
logger.info() ---> entradas con etiqueta INFO en el fichero de logs
logger.warn() ---> entradas con etiqueta WARN en el fichero de logs
logger.error() ---> entradas con etiqueta ERROR en el fichero de logs


En el fichero /var/log/socket-server/socket-server.log tendremos contenido del siguiente tipo a medida que vayan conectando diferentes clientes:

2017-02-02 21:24:29,701 INFO [Thread-1] -- New connection from 192.168.0.143 -- Active threads: 1
2017-02-02 21:24:35,704 INFO [Thread-1] -- 192.168.0.143 -- Received: hola, que tal?
2017-02-02 21:24:46,697 INFO [Thread-2] -- New connection from 192.168.0.145 -- Active threads: 1
2017-02-02 21:24:51,331 INFO [Thread-2] -- 192.168.0.145 -- Received: buenos dias
2017-02-02 21:31:30,555 INFO [Thread-3] -- New connection from 192.168.0.89 -- Active threads: 1
2017-02-02 21:31:40,561 ERROR [Thread-3] -- 192.168.0.89 -- Timeout on data transmission ocurred after 10 seconds.

Si dejáramos la aplicación corriendo varios días como servicio (más adelante veremos como hacerlo) veríamos como el fichero de logs rota cada noche añadiéndose al nombre del fichero al rotar la fecha para tenerlos de este modo clasificados. Al tener más de 10 ficheros de logs al rotar se borrarían automáticamente los más antiguos.