Logging av interne feil med Winston

Winston er et generelt loggingsbibliotek som gir muligheten til å logge hva som helst, hvor som helst i koden, og er et naturlig tillegg til Morgan.

I forrige Node-innlegg satt jeg opp Morgan, som logger HTTP-forespørsler. Men hva med feil på server og i andre interne operasjoner?

Det er her Winston kommer inn: et loggeverktøy som gjerne brukes i kombinasjon med Morgan, og som lar oss loggføre langt flere ting. Den kan også separere loggføringen via såkalte «transports», slik at enkelte feilmeldinger for eksempel kan logges i en database, mens andre sendes til konsollen og/eller lagres til en fil.

Winston er ikke en «middleware» (mellomvare på norsk), på lik linje med Morgan, men et støtteprogram. Konvensjonen er å legge slike i egen mappe utils. Så det første jeg gjorde var å opprette utils/logger/winston.js.

I denne filen startet jobben med å sette opp:

• Hva slags meldinger som skal logges (nivåer)
• Hvor de skal sendes (transports)
• Hvordan de skal formateres

Winston bruker en prioritert skala for graden av logging i applikasjonen, og opererer med følgende fra mest til minst alvorlig:

1. error — noe gikk galt og krever oppmerksomhet
2. warn — noe er mistenkelig, men appen fortsetter
3. info — normale vellykkede operasjoner (oppgave lagret, slettet osv.)
4. debug — detaljert info nyttig under utvikling (f.eks. hva slags data kom inn)

MERK: Programmet tar med alle versjoner fra angitt nivå og oppover. Settes info vil alt fra info og opp til «error» logges.

Jeg startet med å kopiere eksempelet fra NPM:

const winston = require('winston');

const logger = winston.createLogger({
  level: 'info',
  format: winston.format.json(),
  defaultMeta: { service: 'user-service' },
  transports: [
    //
    // - Write all logs with importance level of `error` or higher to `error.log`
    //   (i.e., error, fatal, but not other levels)
    //
    new winston.transports.File({ filename: 'error.log', level: 'error' }),
    //
    // - Write all logs with importance level of `info` or higher to `combined.log`
    //   (i.e., fatal, error, warn, and info, but not trace)
    //
    new winston.transports.File({ filename: 'combined.log' }),
  ],
});

//
// If we're not in production then log to the `console` with the format:
// `${info.level}: ${info.message} JSON.stringify({ ...rest }) `
//
if (process.env.NODE_ENV !== 'production') {
  logger.add(new winston.transports.Console({
    format: winston.format.simple(),
  }));
}

Deretter gjaldt det å finne strategiske steder å logge, og uten at det blir for mye. «Log noise», hvor viktige meldinger drukner i alt for mange loggføringer, kan nemlig fort bli en utfordring.

Jeg ønsket logging av positive hendelser som:

• backup laget
• server startet
• oppgave endret status
• oppgave slettet
• oppgave lagt til

Og logging av feil ved:

• validering av fil
• mislykket backup
• feil ved skriving til fil

Winston og «try/catch»

Implementeringen av Winston gav meg nyttig repetisjon av Javascripts «try/catch» og dens “kasting” av feil, og hvordan dette utarter seg gjennom applikasjonen. Dette omtales gjerne som «bubbling» eller «error propagation».

Målet var å kun loggføre der hvor feilen oppsto. Følgende kode er et godt eksempel på utgangspunktet jeg jobbet ut i fra:

// create a backup
function backup() {
  fs.copyFileSync(tasksFileName, `${tasksFileName}.bak`);
}

// write files
function writeFile(taskObjects) {
  backup();
  fs.writeFileSync(tasksFileName, JSON.stringify(taskObjects, null, 2));
}

// Create todo-object
function taskObjectGenerator(data, taskObjects) {
  if (data && data.trim()) {
    const object = {
      "createdDate": new Date().toISOString().split("T")[0],
      "done": false,
      "id": Date.now(),
      "task": data,
    }
    taskObjects.push(object);
    writeFile(taskObjects);
    return true;
  }
  return false;
};

router.post('/', (req, res) => {
  let body = req.body;
  try {
    let resObj = {};
    let statusCode;
    const taskObjects = validateFile();
    if (typeof body.task === "string" && taskObjectGenerator(body.task, taskObjects)) {
      resObj.data = `Success. To-do ${body.task} created`;
      statusCode = 200;
    } else {
      resObj.data = `Error. Creation of to-do ${body.task} failed. Name, date or ID is missing.`
      statusCode = 400;
    } 
    res
    .status(statusCode)
    .json(resObj);
  } catch (error) {
    res
    .status(error.name === "SyntaxError" ? 400 : 500)
    .send("Something went wrong.");      
  }
});

Ruten POST kaller taskObjectGenerator som kaller writeFile, og writeFile kaller backup. I dette eksempelet har ingen av funksjonene noen «try/catch». Dersom de feiler, vil feilen “boble” oppover og til slutt krasje prosessen, uten mulighet til å registrere feil der hvor de oppstår.

backup er et slikt sted, hvor fanging av feil er viktig, så jeg startet der ved å etablere en «try/catch»-blokk som kaster feilen videre:

function backup() {
  try {
    fs.copyFileSync(tasksFileName, `${tasksFileName}.bak`);
    logger.info(`Backup created`);
  } catch (error) {
    logger.error(`Backup failed: ${error.name} - ${error.message} - ${error.stack}`);
    throw error;
  }
}

Funksjonen ble flyttet inn i try, sammen med en Winston-logging.

I catch logges feilens navn, beskjed og «stack trace», som er en slags brødsmulesti som viser hvor kallet kom fra, før feilen oppsto.

Hvis throw utelates, vil feilen “svelges” i denne catch-en, og resten av applikasjonen vil kjøre videre som om ingen ting har hendt. Det var ikke ønsket oppførsel. Jeg ville ikke at det skulle skrives til fil, hvis backup ikke ble gjennomført.

Oppsummert kan vi si følgende om feilhåndtering med «try/catch»:

• Uten «try/catch» — feilen bobler automatisk oppover til den enten fanges av en catch høyere opp, eller krasjer prosessen hvis ingen fanger den.
• «try/catch» uten throw — feilen slukes, programmet fortsetter som om ingenting skjedde.
• «try/catch» med throw — feilen fanges, du gjør noe (logger), og kaster den videre oppover, noe som vil avbryte den aktuelle operasjonen, men IKKE krasje prosessen, så lenge den fanges opp høyere opp i kjeden.

Der er altså «try/catch» som fanger feilen. En funksjon uten «try/catch» er rett og slett gjennomsiktig for feil — de passerer rett igjennom.

Så, ved feil i backup vil nå ingen av de påfølgende funksjonene i rekken kjøre, og operasjonen dermed avsluttes. Jeg jobbet meg deretter videre oppover i «stack»-en, og la inn «try/catch» også i writeFile, i tilfelle noe skulle gå galt ved skriving til fil eller JSON-parsing:

// write file
function writeFile(taskObjects) {
  try {
    backup();
    fs.writeFileSync(tasksFileName, JSON.stringify(taskObjects, null, 2));
  } catch (error) {
      logger.error(`Write to file failed: ${error.name} - ${error.message} - ${error.stack}`);
      throw error;
  }
}

Men her plasserte jeg backup på en lite hensiktsmessig måte i writeFiles try. Det vil si at hvis backup feiler, vil jeg få dobbel logging. Både i backup selv, men også i writefile. Det er selvsagt unødvendig. Jeg flyttet derfor backup ut av try. Det er som nevnt konvensjon å logge feilen der hvor den oppstår.

// write file
function writeFile(taskObjects) {
  backup();
  try {
    fs.writeFileSync(tasksFileName, JSON.stringify(taskObjects, null, 2));
  } catch (error) {
      logger.error(`Write to file failed: ${error.name} - ${error.message} - ${error.stack}`);
      throw error;
  }
}

taskObjectGenerator trenger ingen «try/catch» slik jeg vurderer det, siden den kun oppretter et objekt og kaller writeFile. Validering av inndata er allerede ivaretatt. Det er ikke slik at man trenger try/catch overalt, bare der man faktisk vil gjøre noe med feilen.

Jeg oppdaterte også validateFile med «try/catch» og logging:

function validateFile() {
  // create file if it doesnt exist
  try {
    if (!fs.existsSync(`./${tasksFileName}`)) {
      fs.writeFileSync(tasksFileName, "[]");
      logger.info('File created');
    }
    return JSON.parse(fs.readFileSync(tasksFileName, "utf8"));
  } catch (error) {
    logger.error(`Error during file validation: ${error.name} - ${error.message} - ${error.stack}`);
    throw error;
  }
}

Også POST-ruten, det øverste stadiet, fikk «try/catch».

router.post('/', (req, res) => {
  let body = req.body;
  try {
    let resObj = {};
    let statusCode;
    const taskObjects = validateFile();
    if (typeof body.task === "string" && taskObjectGenerator(body.task, taskObjects)) {
      resObj.data = `Success. To-do ${body.task} created`;
      statusCode = 200;
      logger.info(`Success. To-do ${body.task} created`)
    } else {
      resObj.data = `Error. Creation of to-do ${body.task} failed. Name, date or ID is missing.`;
      logger.warn(`Error. Creation of to-do ${body.task} failed. Name, date or ID is missing.`)
      statusCode = 400;
    } 
    res
    .status(statusCode)
    .json(resObj);
  } catch (error) {
    res
    .status(error.name === "SyntaxError" ? 400 : 500)
    .send("Something went wrong.");
    logger.error(`Error: ${error.name} - ${error.message}. Task not created`);
    logger.debug(`Incoming body keys: ${Object.keys(body)}`);
  }
});

Her la jeg til en debug-logging for ekstra informasjon, som kun registreres dersom programmet kjører i «developer»-modus, men også her i POST hadde jeg noen unødvendige linjer.

I catch-blokken logger jeg en error, men det er egentlig overflødig, siden jeg logger i både writeFile og backup, som kjøres som en del av opprettelsen av en oppgave. Og jeg logger jo «stack trace» i de meldingene, slik at jeg kan se hvilke funksjoner og ruter som har kalt funksjonen som feiler.

Legg merke til at jeg lot loggingen stå i if-else-blokken. Det er fordi dette er et nivå som ikke innebærer noen funksjoner som logger. Men jeg angir det som «warn», ikke «error», fordi i dette tilfelle er det ikke en feil i programmet, men i dataene fra klienten.

## Konsepter

Jeg brukte litt tid på å forstå «try/catch» under denne øvelsen, noe som var veldig nyttig. I tillegg lærte jeg et par andre viktige konsepter:

- «fail fast»: sørg for å håndtere feil kjapt
- separation of concerns: del opp koden i hensiktsmessige deler
- «log noise»: unngå å logge alt for mye. Det vil bare skape uoversiktlige og massive logg-filer
- centralized error handling: feil bobler til et sted som tar seg av responsen til klienten
- logg der feilen faktisk oppstår, ikke overalt den passerer gjennom

Merk: «try/catch» har også finally, en blokk som kjører kode etter «try/catch» uavhengig av om feilen fanges eller «kastes». En finally-blokk vil alltid kjøre, og brukes gjerne for å rydde ressurser, stenge nettverkstilkoblinger og nullstille kode.

Til slutt testet jeg ulike scenarier med Curl, for å sjekke om loggene fungerte, og at logikken og nivå var korrekt. Her følger et utdrag:

```text
Example app listening on port 3000
info: Server started {"service":"todo-app","timestamp":"2026-06-04T20:32:35.244Z"}
info: List of tasks delivered {"service":"todo-app","timestamp":"2026-06-04T20:32:49.864Z"}
info: Backup created {"service":"todo-app","timestamp":"2026-06-04T20:33:16.081Z"}
info: Success. To-do Lære Winston created {"service":"todo-app","timestamp":"2026-06-04T20:33:16.081Z"}
error: Error. Creation of to-do 123 failed. Name, date or ID is missing. {"service":"todo-app","timestamp":"2026-06-04T20:33:35.335Z"}
info: Backup created {"service":"todo-app","timestamp":"2026-06-04T20:35:17.969Z"}
info: TO-DO with ID 1778914531405 created. {"service":"todo-app","timestamp":"2026-06-04T20:35:17.969Z"}
info: Backup created {"service":"todo-app","timestamp":"2026-06-04T20:35:46.333Z"}
info: TO-DO with ID 1778914531405 created. {"service":"todo-app","timestamp":"2026-06-04T20:35:46.334Z"}
warn: No ID with given ID 999999 found. {"service":"todo-app","timestamp":"2026-06-04T20:36:08.069Z"}
info: Backup created {"service":"todo-app","timestamp":"2026-06-04T20:36:39.512Z"}
info: Task with ID 1778914531405 deleted. {"service":"todo-app","timestamp":"2026-06-04T20:36:39.513Z"}
warn: Error. No to-do with ID 999999 found {"service":"todo-app","timestamp":"2026-06-04T20:37:07.485Z"}

Med både Winston- og Morganlogging på plass føler jeg meg klar til neste steg, som er testing med Jest: et verktøy som hjelper oss å unngå feil ved å teste hver individuelle funksjon.