La lliçó anterior va deixar en Jordi Sala amb una alerta a la mà: ComandesBurnRateRapid, el 8 % de les comandes falla. Les mètriques li diuen quant i des de quan; no li diuen quines comandes, ni a quin servei, ni per què. Al monòlit de Quilòmetre Zero la resposta era a un grep de distància en un únic fitxer de log. Avui una comanda travessa Kong, tres rèpliques de comandes, dues d'inventari, pagaments, un tòpic de Kafka i analitica, cadascun escrivint al seu propi contenidor; el log de la comanda P-2026-000125 està repartit en set llocs i en cap no es diu igual. Aquesta lliçó construeix els altres dos pilars de l'observabilitat: logs estructurats i centralitzats, perquè un identificador reuneixi tot el que va passar amb una petició, i traces distribuïdes, per veure el recorregut i el temps d'aquesta petició per tots els serveis. Al final, els tres senyals queden units a Grafana: de la mètrica que alerta, a la traça que localitza, al log que explica.

1. Per què tail -f ja no serveix
2. Logs estructurats: camps estàndard, nivells i què no cal registrar
3. Pipeline de recollida: agent, magatzem i consulta
4. serveis/comu/logs.py: JSON amb trace_id injectat
5. Traçabilitat distribuïda: traces, spans i context
6. Instrumentació amb OpenTelemetry: serveis/comu/traces.py
7. Collector, backends i mostreig
8. Una traça de "crear comanda" comentada
9. Unir els tres senyals
10. Errors comuns i consells
11. Exercicis i solucions
12. Conclusió

En una màquina, un log és un fitxer i un incident s'investiga amb tail -f, grep i less. En un sistema distribuït això deixa de funcionar per raons que no són de comoditat, sinó estructurals:

• La informació d'una petició està repartida. Crear la comanda P-2026-000125 genera línies a Kong, comandes, inventari, pagaments i analitica. Per reconstruir la història cal obrir cinc terminals i endevinar quina línia de cadascuna correspon a aquesta comanda.
• Els rellotges no coincideixen. Com es va veure a 01-05, ordenar per timestamp línies de màquines diferents pot invertir causa i efecte. Cal un identificador de correlació, no només l'hora.
• Els contenidors són efímers. Quan Kubernetes (07-05) reemplaça un pod de comandes, el seu log desapareix amb ell. Si la fallada va passar just abans de morir, s'ha perdut l'evidència.
• El format lliure no es consulta. Comanda 125 rebutjada per estoc (tomaquet-rosa) és llegible per a una persona; per preguntar "quants rebutjos per estoc de tomaquet-rosa a Lleida en la darrera hora" cal parsejar amb expressions regulars fràgils.
• Volum. 140 repartidors enviant una posició cada 5 s, 100 peticions/s a comandes: són milions de línies al dia. Ningú no les llegeix; cal poder filtrar-les.

La solució té dues parts: que cada servei escrigui logs estructurats amb camps comuns, i que un pipeline els reculli de tots els nodes en un magatzem central consultable.

Un log estructurat és un registre amb camps amb nom, normalment una línia JSON per esdeveniment:

Els camps que tots els serveis de km0/ inclouen sempre:

Els camps específics (comanda_id, producte, replica) s'afegeixen com a claus addicionals, no dins del missatge. I sí: aquí comanda_id és benvingut. El que a les mètriques era un problema de cardinalitat (07-01) als logs és exactament el que es busca, perquè un log s'indexa per text o per unes poques etiquetes, no crea una sèrie per valor.

Els logs viatgen per la xarxa, s'emmagatzemen mesos i els llegeix molta gent. Tot el que el Mòdul 6 va protegir amb xifratge i control d'accés pot acabar en clar en un log si no es vigila:

• Secrets: tokens JWT (ni tan sols "per depurar"), contrasenyes, credencials de Vault, claus d'API de la passarel·la de pagaments, capçaleres Authorization completes. Una traça HTTP en debug que aboqui capçaleres és una fuita.
• Dades personals en clar: nom, email, telèfon i adreça de l'Anna. Es registra usuari: "u:9f1c3a" (el pseudònim de 06-02) i comanda_id; qui necessiti el telèfon l'obté de la base de dades amb el seu permís i la seva auditoria.
• Dades de targeta: mai, de cap manera (06-02).
• Cossos complets de peticions: a més de dades personals, són enormes. Es registren els camps rellevants triats un a un.

Els logs d'auditoria de 06-05 (qui va fer què, hash encadenat, object lock a MinIO) són un canal diferent amb garanties diferents: immutabilitat i retenció llarga. Els logs operatius d'aquesta lliçó són per diagnosticar, es retenen setmanes i es poden esborrar; no s'han de barrejar.

Cada servei escriu JSON a stdout (no en fitxers propis: el contenidor no ha de saber on acaben els seus logs). Un agent per node llegeix la sortida de tots els contenidors del node, hi afegeix etiquetes (servei, instància, node) i envia al magatzem central. La consulta es fa des d'una interfície que entén el format.

Loki contra Elasticsearch, que és la decisió d'arquitectura real:

Quilòmetre Zero tria Loki perquè el seu patró de consulta és gairebé sempre "servei + rang + trace_id", l'emmagatzematge va a MinIO i ja fa servir Grafana i Prometheus. La cardinalitat torna a importar, aquest cop a les etiquetes de Loki: servei, instancia i nivell són etiquetes; trace_id, comanda_id i usuari no ho són (crearien un stream per valor), es busquen dins del contingut amb | json | trace_id="...".

Els logs creixen sense límit si ningú no decideix el contrari. Una política típica: debug no s'envia en producció; info es conserva 14 dies; warning/error 90 dies; els logs de Kong (una línia per petició) 30 dies; els d'auditoria són un altre sistema amb anys de retenció. A Loki la retenció es configura per stream i els chunks antics s'esborren del bucket. Reduir el volum en origen (no registrar cada posició de repartiment, sinó un resum per minut i els rebutjos) sol ser la mesura més eficaç.

Configuració mínima de Promtail i Loki a docker-compose.yml:

Amb structlog, cada servei configura un sol cop el logger i després fa servir log.info("esdeveniment", clau=valor). Un processor consulta el context d'OpenTelemetry (secció 6) i afegeix trace_id i span_id si hi ha un span actiu:

Com es fa servir a comandes, amb el middleware que captura l'X-Request-Id que Kong propaga:

Detalls que convé notar:

• structlog no formata cadenes: log.warning("reserva_estoc_rebutjada", producte=...) produeix claus separades. Escriure log.warning(f"Rebutjat {producte}") funciona, però perd l'estructura. La disciplina és "nom d'esdeveniment estable + camps".
• El processor censurar és una xarxa de seguretat, no la política: la política és no passar aquestes dades. Però costa poc i evita que un log.debug("peticio", headers=dict(request.headers)) d'un dimarts a la nit acabi abocant tokens.
• El trace_id es llegeix del span actiu d'OpenTelemetry. Sense traces configurades, el context és invàlid i simplement no apareix; amb elles, cada línia de log de qualsevol servei que participi en la mateixa petició porta el mateix trace_id, encara que els serveis no hagin fet res explícit per passar-lo.

Consultes LogQL a Grafana:

La segona consulta mostra un ús valuós: mètriques a partir de logs per a preguntes que no mereixen una mètrica pròpia (07-01, exercici 1) però que sí que es volen graficar de tant en tant.

Els logs amb trace_id responen "què va passar"; les traces responen "per on va passar i quant va trigar cada pas". El model, heretat de Dapper (Google) i estandarditzat per OpenTelemetry:

• Una traça és l'arbre complet de feina causat per una petició externa. S'identifica per un trace_id de 128 bits.
• Un span és una unitat de feina amb nom, inici, fi, atributs (comanda_id, rpc.method, db.statement), estat (OK/ERROR) i esdeveniments. Té span_id i un parent_span_id, llevat de l'arrel.
• El context de propagació és el que viatja d'un servei a un altre perquè el span del receptor pengi de l'emissor. L'estàndard és W3C Trace Context: una capçalera traceparent:

(I una tracestate opcional per a dades de proveïdors.) A HTTP i gRPC és una capçalera; a Kafka, una capçalera del missatge; a la saga, es desa juntament amb l'estat a la taula sagas perquè la compensació hores després continuï penjant de la traça original.

OpenTelemetry (OTel) aporta tres coses: un SDK que crea spans i gestiona el context, instrumentacions automàtiques per a llibreries conegudes (gRPC, FastAPI, psycopg, redis, requests, kafka-python/confluent-kafka), i un protocol d'exportació (OTLP) cap a un Collector o un backend. Els serveis de km0/ comparteixen la configuració:

Com ho fa servir comandes en publicar l'esdeveniment després de la saga, i analitica en consumir-lo:

Dos aclariments:

• gRPC, HTTP i PostgreSQL no requereixen codi: els instrumentors intercepten les crides, creen spans i posen/llegeixen traceparent a les metadades. A inventari, AuthInterceptor i el MetriquesInterceptor de 07-01 conviuen amb l'interceptor d'OTel; l'ordre no afecta el context.
• Kafka sí que requereix propagació manual (o l'instrumentor de confluent-kafka, que fa el mateix per sota): el missatge és una dada inert que es consumeix més tard, en un altre procés; ningú no el "crida". El mateix passa amb la saga: saga_comanda.py desa traceparent a la fila de la taula sagas, i quan el relay de l'outbox o una compensació reprenen la feina, reconstrueixen el context amb propagate.extract sobre aquest valor. Sense això, la compensació de P-2026-000125 apareixeria com una traça òrfena sense cap relació amb la comanda.

Els serveis no envien les traces al backend directament, sinó a l'OpenTelemetry Collector: un procés intermedi que rep OTLP, processa (afegeix atributs, filtra, agrupa, mostreja) i exporta a un o diversos destins. Avantatges: els serveis només coneixen un endpoint; canviar de Jaeger a Tempo és canviar el Collector; el mostreig de cua es fa allà.

Quilòmetre Zero fa servir Tempo, amb els blocs al bucket km0-traces de MinIO, per coherència amb Loki i Grafana.

Desar totes les traces de 100 peticions/s amb 8-12 spans cadascuna és car i gairebé inútil: la majoria són idèntiques i correctes. Dues estratègies:

L'habitual, i el que fa km0/, és combinar-los: un ParentBased a l'SDK perquè la decisió sigui coherent a tota la traça, un ratio alt en origen (o 100 % en serveis de poc trànsit) i tail sampling al Collector per quedar-se amb el que és interessant.

Així apareix a Grafana (Tempo) la traça 4bf92f35... de la comanda P-2026-000125 de l'Anna, que va trigar 482 ms i va acabar bé. El sagnat indica la relació pare-fill:

El que la traça explica i les mètriques no podien:

• Dels 482 ms, 318 són la passarel·la de pagaments externa. Res a km0/ no els pot accelerar; sí que es pot paral·lelitzar la reserva i el cobrament, o acceptar la comanda "pendent de confirmar" (07-04).
• L'UPDATE d'inventari va trigar 98 ms en una operació que normalment en triga 2: hi ha contenció de bloqueig sobre vi-crianca (la Setmana de la Verema, moltes comandes del mateix producte). La mètrica p99 de ReservarEstoc la mostrava pujant; la traça diu en quina sentència.
• El span d'analitica pertany a la mateixa traça encara que passi després de la resposta: és l'efecte de propagar traceparent a les capçaleres Kafka.
• Cada span porta el trace_id, i per tant un clic porta a les línies de log dels cinc serveis amb aquest identificador, en ordre.

L'observabilitat no són tres eines, sinó un recorregut: la mètrica diu que alguna cosa va malament, la traça diu on, el log diu per què. Grafana permet que aquest recorregut siguin tres clics:

• Exemplars: Prometheus pot desar, al costat de cada bucket de l'histograma, el trace_id d'una observació recent. A prometheus_client es passa exemplar={"trace_id": ...} a observe(); al gràfic del p99, cada punt té un rombe que obre aquesta traça. És l'enllaç mètrica → traça.
• Enllaç log ↔ traça: el datasource de Loki a Grafana es configura amb una derived field que reconeix trace_id al JSON i mostra un botó "veure traça a Tempo"; i Tempo, a la inversa, amb "logs d'aquesta traça" que llança {servei=~".+"} | json | trace_id="..." a Loki.
• Traça → mètrica: Tempo pot generar mètriques RED a partir dels spans (span metrics), útil per a serveis sense instrumentar amb Prometheus.

Un exemple d'exemplar a metriques.py (07-01), ara que existeix el context de traça:

Amb això, el dissabte a les 10:13 el recorregut d'en Jordi és: alerta ComandesBurnRateRapid → panell amb la taxa d'error → rombe d'exemplar sobre el pic → traça d'una comanda fallida amb el span ReservarEstoc en vermell i rpc.grpc.status_code=UNAVAILABLE → "logs d'aquesta traça" → {"esdeveniment": "circuit_obert", "dependencia": "inventari"}... que és on entra la resta del mòdul.

• Logs de text lliure "perquè es llegeixen millor". Es llegeixen millor un a un; no es consulten. Nom d'esdeveniment estable + camps; per llegir en local, structlog té un renderitzador de consola amb colors.
• Promocionar trace_id o comanda_id a etiqueta de Loki. Cada valor crea un stream i Loki es degrada igual que Prometheus amb cardinalitat alta. Etiquetes: servei, instancia, nivell, entorn. La resta, al JSON.
• Registrar capçaleres o cossos complets en debug i deixar-ho activat. És la fuita de tokens i dades personals més habitual. Un processor de censura com a xarxa, i debug apagat per defecte.
• Perdre el context als salts asíncrons. Un ThreadPoolExecutor, un asyncio.create_task o un missatge Kafka sense propagate.inject trenquen la traça. Davant d'una traça que "s'acaba de sobte", busca el salt sense propagació.
• Mostreig només en capçalera. Descarta el 90 % dels errors. Tail sampling al Collector per quedar-se amb errors i traces lentes.
• Traces sense atributs de negoci. Un span POST /comandes sense km0.comanda_id obliga a buscar per temps. Afegeix l'identificador de domini com a atribut (a traces i logs no hi ha problema de cardinalitat).
• Confondre logs operatius amb auditoria. Retenció, immutabilitat i accés són diferents (06-05). Ni l'auditoria va a Loki amb 14 dies, ni els logs de depuració van al bucket amb object lock.
• Enviar traces directament al backend des de cada servei. Acobla tots els serveis al backend i fa impossible el tail sampling. Un Collector al mig.

Exercici 1. En Marc reporta a suport que la seva comanda de la Setmana del Formatge Artesà "ha donat error" i aporta l'X-Request-Id que la web li ha mostrat: 7a1b.... La Marta obre Grafana. (a) Escriu la consulta LogQL que reuneix tot el que va passar amb aquesta petició a tots els serveis. (b) La consulta retorna línies de Kong i comandes amb trace_id 9c4d..., però cap d'inventari; en canvi, hi ha línies d'inventari amb un trace_id diferent al mateix segon. Què s'ha trencat i on ho buscaries? (c) La Marta troba a la línia de comandes el camp "usuari": "u:2b77e1". Com confirma que és en Marc sense que ningú més no ho pugui fer pel seu compte, i per què el log no conté el seu email?

Exercici 2. L'equip decideix que repartiment publiqui una línia de log per cada posició rebuda (140 repartidors, una cada 5 s) amb el nivell info, i que debug inclogui el cos del missatge. (a) Calcula quantes línies al dia genera només repartiment i estima el volum si cada línia ocupa 350 bytes. (b) Proposa una alternativa que conservi la capacitat d'investigar "per què el panell mostrava furgoneta-3-017 a Girona quan era a Lleida" sense aquest volum. (c) Quin problema de privadesa afegeix el debug amb el cos, i amb quin mecanisme d'aquesta lliçó el mitigaries com a últim recurs?

Exercici 3. La traça de la secció 8 mostra 318 ms a la passarel·la de pagaments i 98 ms d'espera de bloqueig a inventari. Un company proposa "posar TraceIdRatioBased(1.0) a tots els serveis per no perdre cap traça com aquesta". (a) Calcula quants spans per segon rebria el Collector amb 100 peticions/s a comandes i 12 spans per traça, més el trànsit de cataleg (400 peticions/s, 4 spans). (b) Explica per què la configuració d'otel-collector.yaml de la secció 7 ja hauria conservat aquesta traça encara que el ratio fos 0,1, i què hauria passat si el ratio 0,1 s'hagués configurat sense ParentBased. (c) Un span de la compensació de la saga, executat dues hores després que la comanda fallés, apareix com a traça nova i no dins de la de la comanda. Què hi falta i on?

Exercici 1.

(a) {servei=~".+"} | json | request_id="7a1b...", amb el rang de temps acotat al moment de la comanda (Loki escaneja el contingut, així que el rang importa). (b) Kong i comandes comparteixen trace_id, per tant la propagació HTTP funciona; inventari té un altre trace_id al mateix instant, per tant inventari està creant traces noves en lloc de continuar la de comandes: el traceparent no arriba a les metadades gRPC o no es llegeix. Sospitosos per ordre: GrpcInstrumentorClient no instrumentat a comandes (el client no injecta), un interceptor propi a inventari que reconstrueix les metadades i descarta traceparent (revisar AuthInterceptor/ServeiInterceptor de 06-04), o un stub gRPC creat abans de cridar configurar_traces. Es comprova amb un log.debug de les metadades rebudes a inventari (censurant authorization) o mirant a Tempo si el span servidor d'inventari és arrel. (c) La pseudonimització de 06-02 és una funció amb clau (HMAC) sobre l'identificador de l'usuari: la Marta demana al servei d'identitats, amb el seu rol d'operador i el seu tiquet de suport (queda auditat, 06-05), que resolgui u:2b77e1; o calcula el pseudònim del sub d'en Marc i compara. El log no conté l'email perquè és una dada personal que viatja a Loki, a MinIO i a la pantalla de qualsevol amb accés a Grafana: es registra el pseudònim, que no identifica sense la clau, i el comanda_id, que és el que suport necessita.

Exercici 2.

(a) 140 × (86 400 / 5) = 2 419 200 línies al dia; a 350 bytes, uns 847 MB diaris sense comprimir només de posicions, uns 25 GB al mes. (b) Registrar en info només allò anòmal (posicions rebutjades per validació, salts impossibles entre dues posicions, missatges fora d'ordre) i un resum per repartidor i minut (posicions_rebudes, ultima_ts); per reconstruir la ruta de furgoneta-3-017, les dades ja són a repartiment.posicions amb retenció d'hores i al llac HDFS (04-02): investigar consultant aquestes dades, no el log. A més, una traça mostrejada per repartidor cada N missatges dona el recorregut intern sense registrar-los tots. (c) El cos conté la posició exacta d'un empleat amb el seu identificador, una dada personal (06-05, exercici 3); si algú activa debug en producció, es copia a Loki sense les garanties d'accés de repartiment.posicions. Com a últim recurs, el processor censurar amb posicio/lat/lon a CLAUS_PROHIBIDES (i que el cos es registri com a camps, mai com a cadena opaca, perquè el censor pugui actuar); però la política correcta és no registrar el cos.

Exercici 3.

(a) comandes: 100 × 12 = 1 200 spans/s; cataleg: 400 × 4 = 1 600 spans/s; total uns 2 800 spans/s, 242 milions al dia, que el Collector ha de rebre i retenir 10 s cadascun per decidir (uns 28 000 spans en memòria de manera permanent, factible), i dels quals Tempo escriuria el que les polítiques deixin passar. Amb TraceIdRatioBased(1.0) el cost és a la xarxa i al Collector, no a l'emmagatzematge, sempre que hi hagi tail sampling. (b) La traça dura 482 ms i la política lentes conserva tot el que superi 500 ms... no la conservaria per durada; però tampoc no importa: si va tenir un span amb error, la política errors la desa; si no, cau en el 10 % probabilístic. Amb el ratio 0,1 en capçalera, la decisió la va prendre Kong (o comandes) en crear la traça, i ParentBased fa que tots els serveis la respectin: o es mostreja sencera o cap no la genera. Sense ParentBased, cada servei tiraria el seu propi dau: comandes la conservaria i inventari no, i la traça quedaria amb forats (el span ReservarEstoc servidor absent, precisament el dels 98 ms). (c) Falta desar el traceparent de la comanda a la fila de la taula sagas quan es crea la saga, i en executar la compensació reconstruir el context amb propagate.extract sobre aquest valor i crear el span de compensació amb context=ctx (o com a link a la traça original si es prefereix una traça nova enllaçada). És a saga_comanda.py, al punt on el relay o el planificador reprenen una saga pendent.

Amb aquesta lliçó l'observabilitat de Quilòmetre Zero té els seus tres senyals. Els logs deixen de ser text en fitxers de contenidors efímers per ser esdeveniments JSON amb camps comuns (ts en UTC, nivell, servei, instancia, trace_id, request_id, usuari pseudonimitzat, esdeveniment), sense secrets ni dades personals, recollits per Promtail a cada node i emmagatzemats a Loki amb etiquetes de baixa cardinalitat, consultables amb LogQL per l'X-Request-Id que Kong assigna o pel trace_id que OpenTelemetry injecta. Les traces donen el recorregut: spans imbricats amb traceparent W3C propagat per HTTP i gRPC sense codi, i a mà per les capçaleres de Kafka i per la taula sagas, enviats a un Collector que mostreja en cua per conservar errors i lentitud, i emmagatzemats a Tempo. I els tres s'uneixen a Grafana amb exemplars i enllaços log↔traça, de manera que una alerta es converteix en tres clics en una traça amb el span culpable i les línies de log que l'expliquen.

Ja sabem que falla, on i per què. El recorregut d'en Jordi acabava en un log de comandes que deia circuit_obert cap a inventari, i a Tempo un span ReservarEstoc en vermell amb UNAVAILABLE: inventari-1 no respon. La pregunta següent no és d'observabilitat, sinó de supervivència: com detecta la plataforma que un node ha caigut i no simplement va lent? Qui decideix que inv-vlc passi a ser primari, i com s'evita que inv-bcn torni creient que encara ho és? I si el que s'ha perdut no és un procés sinó les dades de km0_inventari de les darreres dues hores? La lliçó següent tracta la gestió de fallades i la recuperació: detecció, failover amb tancat, còpies de seguretat i PITR, i què fer en els minuts en què tot això està passant.