Observation: se var tiden går, utan ett enda nytt beroende

CloudWatch gav loggar och mätvärden men svarade inte på frågan man
faktiskt har när något är långsamt: var tog tiden vägen.

Tjänsterna har medvetet nästan inga beroenden — plattformen har
pg-drivrutinen, orkestern har Claude-klienten. Att dra in ett
OpenTelemetry-SDK med trettio paket för att mäta fyra saker vore fel
avvägning. I stället två standarder som båda bara är text på stdout:

W3C Trace Context. Klienten startar spåret och traceparent följer med
genom plattformen till orkestern, så en teknikers handling går att följa
hela vägen till modellsvaret i stället för att bli två orelaterade spår.

CloudWatch EMF. Strukturerad JSON som CloudWatch själv extraherar
mätvärden ur — ingen agent, ingen SDK, inget som kan sluta fungera tyst.

Varje anrop ger en loggrad med nedbrytning av tiden per del: databasen,
modellanropet, objektlagringen, kundens leverantör. Det svarar direkt på
om ett långsamt ärende beror på S3 eller på Opus-granskningen, i stället
för att någon ska korrelera fem loggrader.

Vägen normaliseras innan den blir dimension, och organisation, ärende-id
och spår-id blir aldrig dimensioner — varje unik kombination är en egen
tidsserie som kostar. De ligger som vanliga fält, sökbara i Logs
Insights. Ett test låser det, eftersom det är precis den sortens sak som
smyger in senare.

Tre larm på det teknikern märker: svarstid p95 över tre sekunder
(medelvärdet döljer att var tjugonde tekniker väntar orimligt länge),
serverfel med spår-id i loggraden, och att modellen avböjer — det senare
tyder på att underlaget innehåller något oväntat, inte på ett driftfel.

Modulen är delad mellan tjänsterna i stället för duplicerad.
Byggkontexten flyttas därför till felsokning/services, och en symlänk gör
att testerna och integrationstestet kör mot samma fil som bilderna.

Verifierat: 106 vitest-tester (10 nya för spårning, EMF-format och att
dimensionerna hålls få), typkontroll, eslint på klient och tjänster,
rotens CI, terraform fmt och referenskontroll på båda lagren, samt
integrationstest mot riktig Postgres där spårraderna syns live.

Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_012EQg3rJsrQ1ZNTvkzmQAtt

felsokning/services/ai-orkester/Dockerfile

@@ -2,9 +2,12 @@
 FROM node:22-alpine
 
 WORKDIR /app
-COPY package.json ./
+COPY ai-orkester/package.json ./
 RUN npm install --omit=dev --no-audit --no-fund && npm cache clean --force
-COPY server.mjs ./
+# Byggkontexten är felsokning/services, så den delade
+# observationsmodulen kan hämtas utan att dupliceras.
+COPY gemensam/observation.mjs ./
+COPY ai-orkester/server.mjs ./
 
 ENV NODE_ENV=production PORT=8080
 USER node

felsokning/services/ai-orkester/observation.mjs

@@ -0,0 +1 @@
+../gemensam/observation.mjs

felsokning/services/ai-orkester/server.mjs

@@ -14,6 +14,7 @@
 import { createServer } from "node:http";
 import { createHmac, timingSafeEqual } from "node:crypto";
 import Anthropic from "@anthropic-ai/sdk";
+import { avsluta, logga, mätvärde, spårFrån, starta } from "./observation.mjs";
 
 const PORT = Number(process.env.PORT ?? 8080);
 const MAX_PROMPT_LANGD = 40000;
@@ -249,6 +250,14 @@ async function lasKropp(req) {
 
 export function skapaServer() {
   return createServer(async (req, res) => {
+    // Spåret kommer från plattformen, så ett långsamt teknikeranrop går
+    // att följa hela vägen till modellsvaret.
+    res.spår = spårFrån(req.headers.traceparent);
+    res.spann = starta("ai-orkester", res.spår);
+    res.on("finish", () =>
+      avsluta(res.spann, { status: res.statusCode, väg: req.url ?? "/", extra: { metod: req.method } }),
+    );
+
     if (req.method === "OPTIONS") {
       res.writeHead(204, {
         "Access-Control-Allow-Origin": "*",
@@ -309,7 +318,8 @@ export function skapaServer() {
 
     try {
       const klient = new Anthropic({ apiKey: apiNyckel });
-      const svar = await klient.beta.messages.create({
+      const svar = await res.spann.mät(`modell_${uppgift}`, () =>
+        klient.beta.messages.create({
         model: konfig.modell,
         max_tokens: konfig.maxTokens,
         output_config: {
@@ -318,9 +328,30 @@ export function skapaServer() {
         },
         betas: ["server-side-fallback-2026-07-01"],
         fallbacks: "default",
-        system: [{ type: "text", text: konfig.system, cache_control: { type: "ephemeral" } }],
-        messages: [{ role: "user", content: innehall }],
-      });
+          system: [{ type: "text", text: konfig.system, cache_control: { type: "ephemeral" } }],
+          messages: [{ role: "user", content: innehall }],
+        }),
+      );
+      // Modellval, token och latens per uppgift. Det är den här
+      // uppdelningen som svarar på om en långsam session beror på
+      // granskningen (Opus, hög effort) eller på något annat.
+      mätvärde(
+        "ModellTokens",
+        (svar.usage?.input_tokens ?? 0) + (svar.usage?.output_tokens ?? 0),
+        "Count",
+        { Uppgift: uppgift, Modell: konfig.modell },
+        {
+          in: svar.usage?.input_tokens ?? 0,
+          ut: svar.usage?.output_tokens ?? 0,
+          cache_las: svar.usage?.cache_read_input_tokens ?? 0,
+          spårId: res.spår.spårId,
+        },
+      );
+
+      if (svar.stop_reason === "refusal") {
+        logga("varning", "modellen avböjde", { uppgift, modell: konfig.modell, spårId: res.spår.spårId });
+        mätvärde("ModellAvbojd", 1, "Count", { Uppgift: uppgift, Modell: konfig.modell });
+      }
       if (svar.stop_reason === "refusal") {
         return svara(res, 502, { error: "AI-tjänsten avböjde förfrågan." });
       }
@@ -328,7 +359,12 @@ export function skapaServer() {
       if (!textBlock) return svara(res, 502, { error: "AI-svaret saknade innehåll." });
       return svara(res, 200, { modell: konfig.modell, svar: JSON.parse(textBlock.text) });
     } catch (fel) {
-      console.error("ai-orkester:", fel);
+      logga("fel", "AI-anropet misslyckades", {
+        uppgift,
+        modell: konfig.modell,
+        spårId: res.spår.spårId,
+        orsak: fel?.message ?? String(fel),
+      });
       return svara(res, 500, { error: "AI-anropet misslyckades." });
     }
   });

felsokning/services/gemensam/observation.mjs

@@ -0,0 +1,166 @@
+// Observation — spårning och mätvärden utan nya beroenden.
+//
+// Tjänsterna har medvetet nästan inga beroenden: plattformen har
+// pg-drivrutinen, orkestern har Claude-klienten. Att dra in ett
+// OpenTelemetry-SDK med trettio paket för att mäta fyra saker vore fel
+// avvägning.
+//
+// I stället två standarder som båda bara är text på stdout:
+//
+//   W3C Trace Context   traceparent-huvudet följer med genom hela
+//                       kedjan, så en teknikers anrop går att följa
+//                       från klienten via plattformen till orkestern.
+//
+//   CloudWatch EMF      strukturerad JSON som CloudWatch själv plockar
+//                       mätvärden ur. Ingen agent, ingen SDK, inget
+//                       som kan sluta fungera tyst.
+//
+// Det som mäts är valt efter en fråga: vad vill man veta klockan tre på
+// natten när något är långsamt? Svaret är var tiden gick — inte hur
+// många anrop som skett.
+
+import { randomBytes } from "node:crypto";
+
+export const NAMNRYMD = "GuidadFelsokning";
+
+const TRACEPARENT = /^00-([0-9a-f]{32})-([0-9a-f]{16})-([0-9a-f]{2})$/;
+
+/**
+ * Läser inkommande traceparent eller startar ett nytt spår.
+ * Ett anrop utan huvud är inte ett fel — de flesta kommer utifrån.
+ */
+export function spårFrån(huvud) {
+  const träff = typeof huvud === "string" ? huvud.trim().match(TRACEPARENT) : null;
+  return {
+    spårId: träff ? träff[1] : randomBytes(16).toString("hex"),
+    förälder: träff ? träff[2] : null,
+    spanId: randomBytes(8).toString("hex"),
+  };
+}
+
+// Skickas vidare till nästa tjänst i kedjan.
+export function traceparent(spår) {
+  return `00-${spår.spårId}-${spår.spanId}-01`;
+}
+
+/**
+ * Ett spann. Mäter tid och samlar barn, så att en logg-rad kan svara på
+ * "var tog tiden vägen" utan att någon behöver korrelera flera rader.
+ */
+export function starta(namn, spår) {
+  const början = process.hrtime.bigint();
+  const barn = [];
+
+  return {
+    namn,
+    spår,
+
+    // Tidtagning på det som faktiskt kan vara långsamt: databasen,
+    // modellanropet, objektlagringen, kundens leverantör.
+    async mät(delnamn, arbete) {
+      const start = process.hrtime.bigint();
+      try {
+        return await arbete();
+      } finally {
+        barn.push({ namn: delnamn, ms: Number(process.hrtime.bigint() - start) / 1e6 });
+      }
+    },
+
+    ms() {
+      return Number(process.hrtime.bigint() - början) / 1e6;
+    },
+
+    delar() {
+      // Samma delnamn flera gånger (t.ex. tre databasfrågor) slås ihop:
+      // antalet och summan säger mer än en lista.
+      const summa = {};
+      for (const d of barn) {
+        summa[d.namn] ??= { antal: 0, ms: 0 };
+        summa[d.namn].antal += 1;
+        summa[d.namn].ms += d.ms;
+      }
+      for (const d of Object.values(summa)) d.ms = Math.round(d.ms * 100) / 100;
+      return summa;
+    },
+  };
+}
+
+// En rad JSON per händelse. CloudWatch Logs Insights kan fråga på
+// vilket fält som helst utan att någon behöver skriva ett regex.
+export function logga(nivå, meddelande, fält = {}) {
+  process.stdout.write(
+    `${JSON.stringify({
+      nivå,
+      meddelande,
+      tid: new Date().toISOString(),
+      ...fält,
+    })}\n`,
+  );
+}
+
+/**
+ * Mätvärden i CloudWatch Embedded Metric Format.
+ *
+ * Formatet är en logg-rad som CloudWatch känner igen och extraherar
+ * mätvärden ur. Poängen är att mätvärdet och sammanhanget står i samma
+ * rad: när latensen är hög går det att gå direkt till anropen som
+ * orsakade den, i stället för att gissa utifrån en graf.
+ *
+ * Dimensioner hålls medvetet få. Varje unik kombination är en egen
+ * tidsserie som kostar, så organisation eller ärende-id får aldrig bli
+ * en dimension — de ligger som vanliga fält.
+ */
+export function mätvärde(namn, värde, enhet, dimensioner = {}, extra = {}) {
+  const nycklar = Object.keys(dimensioner);
+
+  process.stdout.write(
+    `${JSON.stringify({
+      _aws: {
+        Timestamp: Date.now(),
+        CloudWatchMetrics: [
+          {
+            Namespace: NAMNRYMD,
+            Dimensions: nycklar.length > 0 ? [nycklar] : [[]],
+            Metrics: [{ Name: namn, Unit: enhet }],
+          },
+        ],
+      },
+      ...dimensioner,
+      [namn]: värde,
+      ...extra,
+    })}\n`,
+  );
+}
+
+/**
+ * Avslutar ett spann: en strukturerad logg-rad med hela nedbrytningen,
+ * och ett mätvärde för latensen.
+ *
+ * Fel loggas som fel men mäts på samma ställe — annars syns inte att
+ * felen är snabba och de lyckade anropen långsamma, vilket är precis
+ * den sortens sak som förvirrar en felsökning.
+ */
+export function avsluta(spann, { status, väg, extra = {} }) {
+  const ms = spann.ms();
+  const delar = spann.delar();
+
+  logga(status >= 500 ? "fel" : "info", spann.namn, {
+    spårId: spann.spår.spårId,
+    spanId: spann.spår.spanId,
+    väg,
+    status,
+    ms: Math.round(ms * 100) / 100,
+    delar,
+    ...extra,
+  });
+
+  mätvärde("Svarstid", ms, "Milliseconds", { Tjänst: spann.namn, Väg: väg }, { status });
+
+  // En egen serie för fel gör larmet enkelt: larma på summan, inte på
+  // ett förhållande som måste räknas ut.
+  if (status >= 500) {
+    mätvärde("Fel", 1, "Count", { Tjänst: spann.namn, Väg: väg }, { spårId: spann.spår.spårId });
+  }
+
+  return ms;
+}

felsokning/services/plattform/Dockerfile

@@ -2,9 +2,12 @@
 FROM node:22-alpine
 
 WORKDIR /app
-COPY package.json ./
+COPY plattform/package.json ./
 RUN npm install --omit=dev --no-audit --no-fund && npm cache clean --force
-COPY server.mjs bilagor.mjs openapi.yaml ecm-regler.json integrationer.json ./
+# Byggkontexten är felsokning/services, så den delade
+# observationsmodulen kan hämtas utan att dupliceras.
+COPY gemensam/observation.mjs ./
+COPY plattform/server.mjs plattform/bilagor.mjs plattform/openapi.yaml plattform/ecm-regler.json plattform/integrationer.json ./
 
 ENV NODE_ENV=production PORT=8080
 USER node

felsokning/services/plattform/observation.mjs

@@ -0,0 +1 @@
+../gemensam/observation.mjs

felsokning/services/plattform/server.mjs

@@ -26,6 +26,7 @@ import { fileURLToPath } from "node:url";
 import { dirname, join } from "node:path";
 import pg from "pg";
 import { innehallsHash, mediatypGiltig, valjLager } from "./bilagor.mjs";
+import { avsluta, logga, mätvärde, spårFrån, starta, traceparent } from "./observation.mjs";
 
 // API-first: OpenAPI-specen är en versionerad artefakt och serveras live.
 const OPENAPI = readFileSync(join(dirname(fileURLToPath(import.meta.url)), "openapi.yaml"), "utf8");
@@ -59,6 +60,15 @@ const ROLLER = ["tekniker", "arbetsledare", "admin"];
 
 const pool = new pg.Pool({ connectionString: process.env.DATABASE_URL, max: 10 });
 
+// Poolens uttömning är den vanligaste orsaken till att allt blir
+// långsamt samtidigt utan att någon enskild fråga är långsam.
+setInterval(() => {
+  mätvärde("Databaskopplingar", pool.totalCount, "Count", { Tjänst: "plattform" }, {
+    lediga: pool.idleCount,
+    väntande: pool.waitingCount,
+  });
+}, 60_000).unref();
+
 // Var bilagornas innehåll hamnar. Felkonfigurerat s3-läge failar här,
 // vid start, i stället för vid första uppladdningen.
 const BILAGELAGER = valjLager(process.env, pool);
@@ -427,10 +437,10 @@ export async function gorUppslag(def, uppgifter, identifierare, hamtare = fetch)
 // hashen i loggen. Stämmer det inte säger vi det rakt ut i stället för
 // att visa en bild som kan ha bytts ut.
 async function skickaBilaga(res, rad) {
-  const data = await BILAGELAGER.hamta(rad.hash);
+  const data = await res.spann.mät("bilaga_las", () => BILAGELAGER.hamta(rad.hash));
   if (!data) return svara(res, 404, { error: "Innehållet saknas i lagringen." });
   if (innehallsHash(data) !== rad.hash) {
-    console.error("bilaga: innehållet stämmer inte med hashen i loggen", rad.hash);
+    logga("fel", "bilagans innehåll stämmer inte med hashen i loggen", { hash: rad.hash });
     return svara(res, 409, { error: "Innehållet stämmer inte med det som dokumenterades." });
   }
   res.writeHead(200, {
@@ -465,6 +475,22 @@ export function skapaServer() {
 
   return createServer(async (req, res) => {
     res.ursprung = ursprungFor(req);
+
+    // Spåret följer med genom hela kedjan. Kommer inget huvud in startar
+    // vi ett nytt — de flesta anrop kommer utifrån.
+    res.spår = spårFrån(req.headers.traceparent);
+    res.spann = starta("plattform", res.spår);
+    res.setHeader("traceparent", traceparent(res.spår));
+
+    res.on("finish", () => {
+      avsluta(res.spann, {
+        status: res.statusCode,
+        // Ärende- och bilage-id ersätts så att vägen blir en dimension
+        // med rimligt antal värden i stället för en per ärende.
+        väg: (req.url ?? "/").split("?")[0].replace(/\/[A-Za-z0-9_-]{8,}/g, "/:id"),
+        extra: { metod: req.method },
+      });
+    });
     if (req.method === "OPTIONS") {
       res.writeHead(204, {
         "Access-Control-Allow-Origin": res.ursprung,
@@ -787,7 +813,7 @@ export function skapaServer() {
         if (data.length === 0) return svara(res, 400, { error: "Bilagan är tom." });
 
         const hash = innehallsHash(data);
-        await BILAGELAGER.spara(hash, data);
+        await res.spann.mät("bilaga_skriv", () => BILAGELAGER.spara(hash, data));
         const id = `bil-${nyKod()}`;
         await pool.query(
           `insert into bilagor (id, organisation_id, arende_id, hash, mediatyp, storlek, laddad_av)
@@ -937,7 +963,9 @@ export function skapaServer() {
           return svara(res, 500, { error: "Uppgifterna kunde inte läsas — spara om kopplingen." });
         }
 
-        const resultat = await gorUppslag(def, uppgifter, identifierare.trim().toUpperCase());
+        const resultat = await res.spann.mät("leverantorsuppslag", () =>
+          gorUppslag(def, uppgifter, identifierare.trim().toUpperCase()),
+        );
         await pool.query(
           `update integrationer set senast_testad = now(), senaste_status = $3
            where organisation_id = $1 and leverantor = $2`,
@@ -1143,6 +1171,7 @@ export function skapaServer() {
           if (!Array.isArray(handelser) || handelser.length > 500) {
             return svara(res, 400, { error: "Ogiltig händelselista." });
           }
+          res.spann.spår.antalHandelser = handelser.length;
           for (const post of handelser) {
             if (typeof post?.id !== "string" || !post.tidpunkt || typeof post.anvandare !== "string" || !post.handelse) {
               return svara(res, 400, { error: "Ogiltig händelse." });
@@ -1161,7 +1190,14 @@ export function skapaServer() {
 
       return svara(res, 404, { error: "Okänd resurs." });
     } catch (fel) {
-      console.error("plattform:", fel);
+      // Spår-id:t i raden gör att hela kedjan går att hitta i Logs
+      // Insights utifrån larmet.
+      logga("fel", "förfrågan misslyckades", {
+        spårId: res.spår.spårId,
+        väg: vag,
+        metod: req.method,
+        orsak: fel?.message ?? String(fel),
+      });
       return svara(res, 500, { error: "Förfrågan misslyckades." });
     }
   });