Sobre mí¶
- Python, locro y paternidad
- Soy ingeniero y docente, laburo en ShipHero
- Vivo en Anisacate, Córdoba
- Me llevo bien con mis hermanos
Agenda¶
- ¿Para qué loggear?
- Logging 101
- Structlog
- Buenas prácticas
¿Logging? ¿Para qué?¶
- Planificar en el presente para tener, en el futuro, información útil de ejecuciones (pasadas).
- Nos permiten debuggear un problema específico, obtener información de uso, trazabilidad, etc.
- Y también cuantificar para priorizar tareas
Logging 101¶
- Logger: expone la interfaz que se usa desde nuestro código.
- Handler: envía los log records (registros) (creados desde loggers) al destino apropiado (stdout, archivo, red, etc.)
- Filter: excluye o transforma registros.
- Formatter: plantilla para la representación de salida de los registros.
Cada registros, los loggers y los handlers tiene asociado un nivel de severidad,
Existe un método que emite registros con su respectivo nivel logger.debug(), logger.info()...
Y los logger tienen un nivel efectivo necesario.
In [1]:
import logging
In [2]:
root = logging.getLogger()
root
Out[2]:
El logger por defecto "root" tiene nivel mínimo WARNING
In [3]:
root.info("Hola PyConAr") # info < warning => ignorado
In [4]:
root.warning("Dije hola PyConAr!")
Pero también los Handler tienen nivel
In [5]:
otro_logger = logging.getLogger("ejemplo")
otro_logger.setLevel(logging.INFO) # nivel del logger
sh = logging.StreamHandler()
sh.setLevel(logging.WARNING) # nivel del handler
otro_logger.addHandler(sh)
In [7]:
# alcanza el nivel del logger pero no el del handler
otro_logger.info("Te la debo, no estoy en tema") # el registro se crea, pero no se maneja en el handler
In [8]:
otro_logger.warning("veniamos bien, pero pasaron cosas")
Recordemos que un logger puede tener varios handlers
In [9]:
fh = logging.FileHandler('charla.log')
fh.setLevel(logging.INFO)
# le agregamos este nuevo Handler al logger que ya teniamos
otro_logger.addHandler(fh)
In [10]:
# esto no va a stdout pero sí al archivo
otro_logger.info("deberían tener angustia de tomar la decisión, querido Rey, de separarse de España")
In [11]:
!cat charla.log
Nombres y propagación¶
- Cuando instanciamos un logger con
getLoggerpodemos darle un nombre - El nombre determina el namespace (separado por puntos).
- Logs loggers "hijos" heredan la configuración (y pueden sobrecargarla)
La convención es usar la jerarquía completa del módulo
logger = logging.getLogger(__name__)
In [12]:
# reusamos la config del namespace "ejemplo" que tenia `otro_logger`
logger = logging.getLogger('ejemplo.hijo')
logger.info("Hay lugares donde falta el agua, y lugares donde sobra")
In [13]:
!cat charla.log
propagate=True pasa el registro a "loggers padres".
Filtros¶
Transformar o descartar registros
In [14]:
class ShortMsgFilter(logging.Filter):
def filter(self, record):
msg = record.msg
if isinstance(msg, str):
return len(msg) > 10
return False
logger.addFilter(ShortMsgFilter())
logger.warning("hola")
In [15]:
logger.warning("buscaremos otros jueces que nos representen")
¿Cómo configuramos?¶
In [1]:
import logging.config
DEFAULT_LOGGING = {
'version': 1,
'disable_existing_loggers': True,
'loggers': {
'ejemplo': {
'level': 'DEBUG',
'handlers': ["console_handler"]
},
},
"handlers": {
'console_handler': {
'level': 'DEBUG',
'formatter': 'info',
'class': 'logging.StreamHandler',
},
},
"formatters": {
"info": {
'format': "%(asctime)s [%(levelname)s] %(message)s"
},
}
}
logging.config.dictConfig(DEFAULT_LOGGING)
In [2]:
logger = logging.getLogger("ejemplo")
logger.debug("No logramos lograr ese logro")
¿Pero no es muy complicado todo esto?¶
- La configuración no es trivial
- Los default son malos
- ¡Ni siquiera respeta PEP8!
Structlog es a logging lo que requests a httplib
It makes logging in Python less painful and more powerful by adding structure to your log entries.
In [1]:
import structlog
# drop-in replacement!
logger = structlog.get_logger()
logger.info("El oceáno es muy grande y el submarino es muy pequeño")
Lo importante: La mayoría de las veces necesitamos registrar datos¶
(Ejemplos reales del código de mi trabajo, permiso)
In [ ]:
logger.info(
"Reserving inventory for (%s, %d, %d, %d, %d, %d)",
sku,
warehouse_id,
account_id,
priority,
available_inventory,
required_quantity,
)
In [ ]:
logger.warning(
"LineItem points to an non-existent SKU\n"
"LineItem (id, sku, account_id): (%d, %s, %s)\n"
"Order (id, order_number): (%d, %s)",
li.id,
li.sku,
li.account_id,
li.order.id,
li.order.order_number,
)
In [ ]:
logger.info(
"kit_allocations: %r",
[
{
"sku": li.get("sku"),
"quantity": li.get("quantity"),
"quantity_pending_fulfillment": li.get("quantity_pending_fulfillment"),
"quantity_pending_allocation": li.get("quantity_pending_allocation"),
}
for li in kit_allocations
],
)
La manera de structlog es la manera pythonica: keyword arguments!
In [2]:
logger.error("Iniciamos conversaciones", interlocutor="FMI", tipo_acuerdo="stand-by", monto=52e9, moneda="usd")
In [ ]:
structlog.configure
Procesadores¶
En structlog los formatters y filters se unifican en processors,
In [10]:
structlog.configure(
processors=[
structlog.stdlib.add_log_level,
structlog.processors.TimeStamper(fmt="iso"),
structlog.processors.JSONRenderer()
]
)
logger = structlog.get_logger()
logger.warning("todas las tormentas juntas", tipo_conferencia="grabada", lira_turca=25.3)
JSONRenderer usa json.dumps by default (configurable) pero es inteligente
In [13]:
class Periodo:
def __repr__(self):
return "50 años"
p = Periodo()
In [14]:
import json
json.dumps(p)
In [15]:
logger.info("el mejor equipo", periodo=p)
In [16]:
class PeriodoReal(C):
def __structlog__(self):
return "hasta el 11 de agosto"
logger.info("gobierno economico", hasta=PeriodoReal())
Formatos de salida¶
structlog tiene procesadores "amigables" con el desarrollo
In [3]:
import structlog
structlog.configure(
processors=[
structlog.stdlib.add_log_level,
structlog.processors.TimeStamper(fmt="%Y-%m-%d %H:%M.%S"),
structlog.dev.ConsoleRenderer()
]
)
logger = structlog.get_logger()
logger.info("es todo mentira", tema="autopistas")
En producción: json¶
- JSON un formato amigable con humanos, y universal para compartir datos.
- No hace falta regex ni nada para parsear, vienen con estructura y tipo de datos básicos!
- Muchos sistemas habilitan busqueda avanzada
**Ejemplo de Cloudwatch
Contextos¶
In [1]:
%%writefile a_module.py
from structlog import get_logger
logger = get_logger()
def some_function():
logger.error("escuchas", tipo="ilegales", respuesta="cuentapropistas")
In [8]:
import sys
import logging
import structlog
from a_module import some_function
logging.basicConfig(
format="%(message)s", stream=sys.stdout, level=logging.INFO
)
structlog.configure(
processors=[
structlog.processors.TimeStamper(fmt="iso"),
structlog.processors.KeyValueRenderer(
key_order=["timestamp", "event"]
),
],
context_class=structlog.threadlocal.wrap_dict(dict),
logger_factory=structlog.stdlib.LoggerFactory(),
)
In [9]:
def entrevista():
log = logger.new(periodista="amigo") # set a new context. any futher event from the logger will get x for free
log.warning("inicio entrevista")
log = log.bind(sobre=4) # update the context
some_function()
log = log.unbind("periodista")
log.warning("final entrevista")
entrevista()
Consejos / Buenas Prácticas¶
A veces loggeamos mucho pero no siempre efectivamente.
- Loggear transiciones de estado
- Mientras más "raro" el evento, mayor nivel y detalle
- ¡Quitar ruido!
Es barato pero no gratis.
- Usar bien los niveles y filtros.
- No duplicar handlers
- Delegar todo lo que se pueda a la "infra" (storage, rotación de archivos)
Además de timestamp, agregar info de trazabilidad: request_id, thread_id, user_id, etc.
- Timestamps en UTC
- Tokens de trazabilidad únicos
Structlog es fácil, poderoso y pythónico: úsenlo!
- también miren Loguru
Configuración
- Tan tarde como se pueda, antes de que comience a ejecutarse tu código
- Procurá que se haga una única vez
- Adaptarse a convenciones del framework (si existen)
- Podés reconfigurar loggers de terceros
- Structlog justo despues de logging estándar, via
stdlib.LoggerFactory
- Usen barbijo y cuídense
Caricias significativas con el codo¶
