Logs: registrar lo necesario para entender un fallo
«Ha fallado» es un mensaje bastante eficiente: ocupa poco y no compromete al programa con ninguna explicación. El problema aparece cuando alguien tiene que averiguar qué pasó. Si han entrado varias importaciones, no sabemos cuál llegó a empezar, qué filas se descartaron ni si el proceso terminó. Hemos ahorrado caracteres a cambio de regalar una investigación al siguiente compañero. Una distribución del trabajo admirable, siempre que no te toque recibirla.
Un log registra eventos de la aplicación. Empezaremos con tres mensajes para reconocer sus niveles antes de construir una revisión completa. Guarda este primer ejemplo como primer_log.py y ejecútalo con python primer_log.py. Los mensajes están elegidos para mostrar INFO, WARNING y ERROR: no demuestran que haya fallado una revisión real. Para ver tres líneas no necesitamos empezar fabricando una clase; mi entusiasmo por la arquitectura también tiene un límite.
import logging
logging.basicConfig(
level=logging.INFO,
format="%(levelname)s | %(message)s",
)
logging.info("revision iniciada")
logging.warning("fila 2 sin codigo")
logging.error("informe no generado")
De tres mensajes a una operación que puedas reconstruir
Verás INFO | revision iniciada, WARNING | fila 2 sin codigo y ERROR | informe no generado, cada mensaje en una línea. basicConfig fija el formato y el umbral INFO; sin esa configuración, el umbral predeterminado es WARNING y el mensaje INFO no aparecería. La salida va por defecto a stderr. Llamar a logging.error escribe un registro: no lanza una excepción ni detiene el programa.
Ya puedes usar el ejemplo básico para distinguir niveles y comprobar qué aparece en la salida. La ampliación siguiente incorpora funciones, diccionarios, JSON y una clase de formato; puedes volver a ella después de practicar clases y objetos. Su objetivo será relacionar los eventos de una misma operación sin copiar las filas completas ni las credenciales. El nivel ERROR por sí solo no identifica qué ejecución falló; la solemnidad de las mayúsculas no aporta ese dato.
También importa el vocabulario. Un evento llamado «importacion.fin» no debería significar unas veces «he terminado de revisar» y otras «he escrito todos los cambios». Aquí significará exclusivamente que se han recorrido las filas. El estado parcial indicará que hubo rechazos. Es una convención del ejercicio; en un producto tendrías que distinguir además validación, preparación y aplicación de cambios. El nombre de un evento puede exagerar tanto como la portada de una demo.
La introducción a logging de Python distingue entre mostrar una salida habitual con print y registrar eventos mediante un logger. Sus niveles permiten expresar la importancia: usaremos INFO para inicio y final, WARNING para una fila descartada y ERROR si la revisión se interrumpe por un fallo inesperado. El nivel no decide si una operación salió bien; eso lo expresa el resultado del proceso.
Ampliación: una revisión con registros JSON
Guarda el siguiente programa, independiente del anterior, como logs_demo.py. Utiliza Python 3.10 o posterior y solo la biblioteca estándar. Revisará datos inventados: aceptará dos filas y rechazará otras dos, con el mismo identificador de operación en todos sus eventos. Cada línea será un objeto JSON independiente para consultar campos sin deducirlos de una frase libre. No modifica ningún modelo ni realiza una importación real:
import json
import logging
import math
import re
import sys
from datetime import datetime, timezone
from uuid import uuid4
class FormatoJSON(logging.Formatter):
def format(self, registro):
datos = {
"fecha": datetime.fromtimestamp(
registro.created, timezone.utc
).isoformat(),
"nivel": registro.levelname,
"evento": registro.getMessage(),
"operacion": registro.operacion,
}
for campo in ("fila", "motivo", "validas", "rechazadas", "estado"):
if hasattr(registro, campo):
datos[campo] = getattr(registro, campo)
return json.dumps(datos, ensure_ascii=True, allow_nan=False)
def crear_logger(salida):
logger = logging.getLogger("importacion_demo")
logger.setLevel(logging.INFO)
for anterior in logger.handlers[:]:
logger.removeHandler(anterior)
anterior.close()
handler = logging.StreamHandler(salida)
handler.setFormatter(FormatoJSON())
logger.addHandler(handler)
logger.propagate = False
return logger
def motivo_rechazo(fila):
if not isinstance(fila, dict):
return "FILA_NO_ES_OBJETO"
codigo = fila.get("codigo")
if not isinstance(codigo, str) or not re.fullmatch(r"[A-Z][A-Z0-9-]{0,39}", codigo):
return "CODIGO_INVALIDO"
area = fila.get("area_m2")
if type(area) not in (int, float):
return "AREA_INVALIDA"
if area <= 0 or (type(area) is float and not math.isfinite(area)):
return "AREA_INVALIDA"
return None
def revisar(filas, logger):
operacion = str(uuid4())
contexto = {"operacion": operacion}
validas = rechazadas = 0
logger.info("importacion.inicio", extra=contexto)
try:
for numero, fila in enumerate(filas, start=1):
motivo = motivo_rechazo(fila)
if motivo:
rechazadas += 1
logger.warning("fila.rechazada", extra={
**contexto, "fila": numero, "motivo": motivo
})
else:
validas += 1
except Exception:
logger.error("importacion.interrumpida", extra={
**contexto, "motivo": "PROCESO_INTERRUMPIDO",
"validas": validas, "rechazadas": rechazadas
})
raise
estado = "parcial" if rechazadas else "completa"
logger.info("importacion.fin", extra={
**contexto, "validas": validas,
"rechazadas": rechazadas, "estado": estado
})
return {**contexto, "validas": validas,
"rechazadas": rechazadas, "estado": estado}
if __name__ == "__main__":
filas = [
{"codigo": "S-01", "area_m2": 12},
{"codigo": "", "area_m2": 8, "nota": "contenido privado ficticio"},
{"codigo": "S-03", "area_m2": -2},
{"codigo": "S-04", "area_m2": 15},
]
revisar(filas, crear_logger(sys.stdout))
La función de revisión recibe su logger. Así podemos dirigir la salida a la consola durante una demostración o a una salida en memoria durante una prueba. La configuración del logger propio del ejemplo se realiza al arrancar, no al importar el módulo. Es una decisión útil cuando empiezas a separar un script en módulos: importar una función no debería reconfigurar silenciosamente los registros de toda la aplicación.
El formateador construye un objeto con campos elegidos. La referencia de logging explica que extra permite añadir atributos al registro. Aquí lo usamos para transportar el contexto; el formateador decide cuáles incorpora a la salida. No volcamos el diccionario interno del registro ni la fila completa. El código de rechazo procede de nuestras reglas y la posición corresponde al orden de entrada, empezando en uno.
Las reglas son deliberadamente pequeñas: código con el patrón indicado y superficie numérica positiva y finita. Un booleano no cuenta como superficie y no convertimos textos a números. Si una fila incumple varias reglas, se registra solo el primer motivo encontrado. Tampoco se comprueban duplicados, unidades recibidas o pertenencia a un catálogo. Eso requeriría otras reglas y otros códigos. El log documenta las decisiones del validador; no amplía sus competencias por llevar fecha.
La lista de campos no es un filtro universal de secretos. Alguien podría cambiar mañana una llamada y poner una contraseña dentro de motivo. La protección del ejemplo depende también de que los eventos y motivos sean textos controlados y de que no introduzcamos datos de entrada en ellos. Esta distinción merece quedarse clara antes de envolverlo en una clase llamada «LoggerSeguro» y dar el problema por domesticado.
Leer el resultado sin confundir un rechazo con un proceso roto
Ejecuta el archivo desde su carpeta:
python logs_demo.py
Verás cuatro líneas JSON. La primera tendrá el evento importacion.inicio; las dos siguientes serán fila.rechazada, para las posiciones 2 y 3, con los motivos CODIGO_INVALIDO y AREA_INVALIDA. La última será importacion.fin, con dos válidas, dos rechazadas y estado parcial. El UUID y las fechas cambiarán en cada ejecución. Las cuatro líneas deben compartir la operación.
Con eso podemos responder una pregunta que «ha fallado» dejaba pendiente: el recorrido terminó y dos filas quedaron fuera por reglas conocidas. No se produjo necesariamente un fallo del programa. El responsable del producto tendrá que decidir si ese resultado permite continuar, si bloquea la entrega o si exige corregir los datos. Subir todos los rechazos a ERROR no toma esa decisión por él; solo añade una alarma a cada fila.
Si se produce una excepción inesperada durante el recorrido, el ejemplo registra importacion.interrumpida y vuelve a lanzarla. No escribe un final normal. Los contadores de ese evento describen lo recorrido hasta ese momento, no el total de entrada. Esta separación continúa lo explicado en errores y excepciones: registrar una incidencia no equivale a recuperarse de ella.
Tampoco una ausencia de final demuestra por sí sola cuál fue la causa. El proceso pudo detenerse sin ejecutar nuestro manejador, la salida pudo perderse o el sistema de registros pudo fallar. Inicio sin final es una pista para investigar, no una prueba automática de que el servidor remoto canceló una operación. Nuestro ejemplo ni siquiera tiene un servidor remoto; me parece un buen momento para no inventárselo en las conclusiones.
Evitar que el diagnóstico se convierta en otra fuga de información
La nota privada ficticia de la segunda fila no aparece en la salida porque nunca se entrega al logger. Lo mismo sucede con cualquier campo adicional que no utilicemos. La guía de logging de OWASP recomienda correlacionar eventos y evitar registrar directamente tokens, contraseñas y otros datos sensibles. En este ejemplo aplicamos esa idea dejando fuera el contenido de las filas y usando un identificador propio de operación.
También evitamos incluir el texto de la excepción inesperada. Un mensaje de otra biblioteca podría contener una URL con credenciales, una ruta privada o una parte del documento. En una aplicación real probablemente necesitarás más detalle para depurar, pero debe ir a un destino de diagnóstico diseñado y revisado para ello. Activar logger.exception indiscriminadamente no es una política de tratamiento de datos; es una manera rápida de descubrir qué secretos conoce cada dependencia.
JSON aporta una estructura y codifica los caracteres de una cadena. No valida que la información de esa cadena deba guardarse. Podemos introducir saltos de línea y marcadores ficticios en una fila para comprobar que no aparecen en los eventos. Eso verifica esta implementación y sus llamadas actuales. Si añadimos campos, hay que revisar de nuevo qué contienen y comprobar su tamaño, tipo y procedencia.
La posición de una fila tampoco basta para encontrarla en cualquier versión posterior del fichero. Tendrás que conservar una referencia controlada a la entrada o al lote correspondiente. Esa referencia puede ser sensible según el proyecto; no pondría por defecto una ruta completa del ordenador de una persona. Saber a qué entrega pertenece una revisión y difundir toda la estructura de carpetas son decisiones bastante distintas.
Conservar menos ruido y una historia que se pueda seguir
Para una herramienta pequeña, la salida a consola puede bastar durante el desarrollo. En un despliegue habrá que decidir dónde se recoge, quién puede consultarla, cuánto se conserva y qué ocurre si ese destino falla. No hay un plazo universal que podamos copiar del tutorial. La política debe responder al uso y a las obligaciones del sistema, sin almacenar indefinidamente todo lo que alguna vez ayudó a depurar.
También revisaría el volumen. Una línea por rechazo sirve para este lote; millones de filas pueden exigir un resumen y un informe de incidencias separado, con acceso apropiado. Registrar cada paso correcto no mejora automáticamente el diagnóstico. A veces solo consigue que el evento importante tarde más en aparecer entre doscientas felicitaciones del programa por haber seguido ejecutándose.
La prueba útil consiste en entregar estos registros a otra persona y pedirle que reconstruya la revisión: una operación, cuatro filas recorridas, dos rechazos identificados y un final parcial. Después conviene probar un recorrido interrumpido y comprobar que nadie lo interpreta como completo. Eso exige eventos y resultados coherentes, no solo comprobar que existe un archivo con extensión log.
Conservaría este criterio al crecer la herramienta: cada campo debe ayudar a responder una pregunta y tener un motivo para estar ahí. Si te ha tocado investigar una automatización, ¿qué dato te faltó y cuál sobraba en su salida? Cuéntalo sin pegar registros privados. Puede que la mejora más útil del siguiente script sea una línea bien pensada; la novela completa de sus variables puede esperar a otra carrera literaria.
Respuestas