1. Registro que sirve para reconstruir lo que pasó

Nivel 10: Saber qué está pasando

La prueba de fuego de un sistema de registro no es que produzca ficheros grandes. Es esta: abre el registro de ayer, elige una compra concreta y explica por qué se hizo, sin mirar el código y sin volver a descargar datos de mercado. Qué precio había, qué señal salió, con qué umbral se comparó, qué tamaño se decidió, qué orden se envió y qué contestó el bróker. Si no puedes reconstruir esa cadena entera, no tienes un registro: tienes frases sueltas con marca de tiempo.

El registro se escribe para tu yo de dentro de tres semanas

Casi todo el mundo escribe registros pensando en la consola que mira mientras desarrolla. Ese es el uso menos importante. El que de verdad importa llega semanas después, cuando alguien pregunta por qué la cartera tenía esa posición un martes por la mañana, el mercado ya se ha movido, el proveedor ha revisado sus datos históricos y tu memoria no sirve de nada.

De ahí salen dos exigencias incómodas. La primera: cada evento tiene que ser autosuficiente. Una línea que diga "señal generada" no vale nada; hacen falta el símbolo, el valor del indicador, el umbral y la fecha de la última vela usada. La segunda: el registro tiene que ser consultable por una máquina. Si para responder una pregunta hay que leer con los ojos diez mil líneas, la respuesta no llegará nunca.

Estructurado quiere decir un diccionario por evento

Un registro estructurado es aquel en el que cada evento es un objeto con campos con nombre, no una frase construida concatenando texto. La frase es cómoda de escribir y horrible de explotar; el objeto es justo al revés. En Python se consigue sin librerías raras: un formateador que serialice a JSON y un hueco por donde meter campos propios.

import json
import logging
import time

class FormateadorJson(logging.Formatter):
    def format(self, registro):
        evento = {
            "ts": time.strftime("%Y-%m-%dT%H:%M:%S", time.gmtime(registro.created)),
            "nivel": registro.levelname,
            "origen": registro.name,
            "evento": registro.getMessage(),
        }
        evento.update(getattr(registro, "campos", {}))
        return json.dumps(evento, ensure_ascii=False, default=str)

manejador = logging.StreamHandler()
manejador.setFormatter(FormateadorJson())
log = logging.getLogger("estrategia")
log.addHandler(manejador)
log.setLevel(logging.INFO)

Con esto, la pregunta "cuántas órdenes se rechazaron el jueves por precio fuera de rango" deja de ser arqueología y pasa a ser un filtro de una línea.

Los dos identificadores que lo cambian todo

Un evento aislado no explica nada; lo que explica es la cadena. Para poder reconstruirla necesitas dos identificadores. El identificador de ejecución se genera una vez al arrancar el proceso y viaja en todos los eventos de esa ejecución: te permite aislar el ciclo de las 9:30 del martes entre miles de líneas. El identificador de orden, que tú generas antes de enviar nada y que el bróker te devuelve como referencia del cliente, cose la decisión con su consecuencia.

La regla práctica es registrar los cinco pasos de toda decisión, siempre en el mismo orden y con los mismos nombres de campo:

Datos de entrada: qué velas se usaron, de qué fuente y con cuánto retraso.
Señal calculada: el valor de la regla, el umbral y la decisión que sale de compararlos.
Tamaño decidido: patrimonio, porcentaje de riesgo, precio de referencia y acciones resultantes.
Orden enviada: símbolo, cantidad, tipo, límite y el identificador de cliente que tú generas.
Respuesta del bróker: su identificador, el estado devuelto y la latencia de la llamada.

import uuid

RUN_ID = uuid.uuid4().hex[:12]

def registrar(nivel, evento, **campos):
    campos.setdefault("run_id", RUN_ID)
    log.log(nivel, evento, extra={"campos": campos})

registrar(logging.INFO, "datos_cargados", simbolo="AAPL", velas=250,
          ultima_vela="2026-08-07", fuente="proveedor_a", retraso_s=41)

registrar(logging.INFO, "senal", simbolo="AAPL", regla="cruce_50_200",
          rapida=189.42, lenta=186.10, umbral=0.0, decision="comprar")

registrar(logging.INFO, "tamano", simbolo="AAPL", patrimonio=100000.0,
          riesgo_pct=0.5, precio_ref=190.05, acciones=26)

id_cliente = uuid.uuid4().hex[:12]
registrar(logging.INFO, "orden_enviada", simbolo="AAPL", acciones=26,
          tipo="limite", limite=190.20, id_cliente=id_cliente)

registrar(logging.INFO, "respuesta_broker", id_cliente=id_cliente,
          id_broker="a1b2c3", estado="aceptada", latencia_ms=118)

Fíjate en el detalle del reintento: si vuelves a enviar la misma orden, el identificador de cliente debe ser el mismo. Si generas uno nuevo, el registro no podrá distinguir nunca un duplicado tuyo de un error del bróker.

Niveles: por qué registrarlo todo a depuración es no registrar nada

Los niveles no están para adornar. Error es algo que ha fallado y alguien tendrá que mirar; aviso es algo raro que el sistema ha absorbido solo; informativo es el rastro de la operativa normal, la cadena de arriba; depuración es el detalle que solo sirve cuando estás persiguiendo un fallo concreto.

Cuando todo se escribe a depuración pasa lo previsible: el volumen entierra los pocos eventos que exigen actuar y nadie los encuentra a tiempo. Un sistema que genera medio millón de líneas al día donde solo veinte importan es funcionalmente ciego. La regla es dejar producción en informativo y poder subir a depuración por símbolo o por módulo cuando hace falta, sin reiniciar nada.

Hay además una razón práctica para ser estricto con los niveles: en el módulo siguiente vas a contar errores por hora como métrica de salud. Si marcas como error todo lo que el sistema absorbe solo, ese contador deja de significar nada. Un reintento que acaba funcionando es un aviso; un reintento que agota sus intentos sí es un error.

Nunca, jamás, las credenciales

Volcar las cabeceras de una petición para depurar un error de autenticación es la forma más común de filtrar una clave. El registro suele acabar en otro sistema, con otra política de acceso, otra retención y a menudo otro proveedor. Un secreto escrito ahí es un secreto que ya no controlas, y da igual que la clave sea de solo lectura: la lista de tus posiciones también es información.

PROHIBIDAS = {"api_key", "api_secret", "passphrase", "authorization", "token"}

def limpiar(campos):
    return {k: ("***" if k.lower() in PROHIBIDAS else v) for k, v in campos.items()}

registrar(logging.DEBUG, "peticion_http", **limpiar({
    "ruta": "/v2/orders", "metodo": "POST",
    "api_key": "tu_clave_aqui", "cuerpo_bytes": 214,
}))

Escenario trabajado: la compra que nadie sabía explicar

Escenario inventado con fines didácticos. Un martes el sistema compra 26 acciones de un valor que llevaba semanas sin señal. Con un registro de frases sueltas, el equipo tarda dos días y acaba encogiéndose de hombros. Con la cadena de arriba, se filtra por identificador de ejecución y aparece en el primer evento: retraso_s=41200, es decir, la última vela usada era de hacía casi doce horas porque el proveedor sirvió datos cacheados. La señal era correcta sobre datos incorrectos. Sin ese campo en el evento de carga, esa conclusión no se alcanza nunca.