1. Logging that lets you reconstruct what happened
Level 10: Knowing what is going on
The acid test of a logging system is not that it produces big files. It is this: open yesterday's log, pick one particular buy and explain why it happened, without looking at the code and without downloading market data again. What the price was, what signal came out, what threshold it was compared against, what size was decided, what order was sent and what the broker replied. If you cannot reconstruct that whole chain, you do not have a log: you have loose sentences with a timestamp.
The log is written for you three weeks from now
Almost everybody writes logs with the console they watch while developing in mind. That is the least important use. The one that really matters comes weeks later, when somebody asks why the portfolio held that position on a Tuesday morning, the market has already moved, the provider has revised its historical data and your memory is no use at all.
Two uncomfortable requirements follow. The first: every event has to be self-sufficient. A line saying "signal generated" is worth nothing; you need the symbol, the indicator's value, the threshold and the date of the last candle used. The second: the log has to be machine-queryable. If answering a question means reading ten thousand lines with your eyes, the answer will never arrive.
Structured means one dictionary per event
A structured log is one in which each event is an object with named fields, not a sentence built by concatenating text. The sentence is convenient to write and horrible to exploit; the object is exactly the other way round. In Python you get it without exotic libraries: a formatter that serializes to JSON and a slot for putting your own fields in.
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)With this, the question "how many orders were rejected on Thursday for a price out of range" stops being archaeology and becomes a one-line filter.
The two identifiers that change everything
An isolated event explains nothing; what explains is the chain. To be able to reconstruct it you need two identifiers. The run identifier is generated once when the process starts and travels in every event of that run: it lets you isolate Tuesday's 9:30 cycle among thousands of lines. The order identifier, which you generate before sending anything and which the broker returns to you as the client reference, stitches the decision to its consequence.
The practical rule is to log the five steps of every decision, always in the same order and with the same field names:
- Input data: which candles were used, from which source and with how much delay.
- Signal computed: the rule's value, the threshold and the decision that comes out of comparing them.
- Size decided: equity, risk percentage, reference price and resulting shares.
- Order sent: symbol, quantity, type, limit and the client identifier you generate.
- Broker's reply: its identifier, the status returned and the call's latency.
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)Note the detail about retries: if you resend the same order, the client identifier must be the same one. If you generate a new one, the log will never be able to tell a duplicate of yours from a broker error.
Levels: why logging everything at debug is logging nothing
Levels are not decoration. Error is something that has failed and somebody will have to look at; warning is something odd the system absorbed on its own; info is the trace of normal operation, the chain above; debug is the detail that only helps when you are chasing a particular failure.
When everything is written at debug the predictable happens: the volume buries the handful of events that demand action and nobody finds them in time. A system generating half a million lines a day where only twenty matter is functionally blind. The rule is to leave production at info and to be able to raise to debug per symbol or per module when needed, without restarting anything.
There is also a practical reason to be strict with levels: in the next module you are going to count errors per hour as a health metric. If you mark as an error everything the system absorbs on its own, that counter stops meaning anything. A retry that ends up working is a warning; a retry that exhausts its attempts is indeed an error.
Never, ever, the credentials
Dumping a request's headers to debug an authentication error is the most common way of leaking a key. The log usually ends up in another system, with another access policy, another retention period and often another provider. A secret written there is a secret you no longer control, and it makes no difference that the key is read-only: the list of your positions is information too.
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,
}))Worked scenario: the buy nobody could explain
A scenario invented for teaching purposes. One Tuesday the system buys 26 shares of a name that had gone weeks without a signal. With a log of loose sentences, the team spends two days on it and ends up shrugging. With the chain above, you filter by run identifier and it shows up in the first event: retraso_s=41200, that is, the last candle used was almost twelve hours old because the provider served cached data. The signal was correct on incorrect data. Without that field in the load event, that conclusion is never reached.