Att utveckla för driftbarhet

Ordet systemutveckling syftar till att handla om mer än programmering av affärslogik. Det syftar till att utveckla systemet som ska skapa affärsvärde. Har man väl vridit hjärnan till ett sådant tankesätt, är det lätt att ta till sig att saker som hur loggar skrivs ut potentiellt kan vara en väldigt viktig del av programmeringen. Den stackars jourpersonen som kl 03 ska försöka reda ut varför företaget plötsligt blöder pengar, vill nog gärna att Nagios, Hyperiq eller vad man nu använder; triggas på rätt sätt. Övervakningssystem som dem tittar ofta på loggar för att rapportera fel. Det betyder att loggar potentiellt kan vara väldigt viktiga == bör testas! Nedan visas ett exempel på hur vi gjorde ett enkelt test för att verifiera själva logutskriften hos en kund.
Vi tänker oss att vi har en service “MyService” som använder sig av en wrapper “RemoteProviderWrapper” för att anropa en extern tjänst av något slag.

package se.diabol.test.logunit
import org.apache.log4j.Logger
class MyService {
  private Logger log = Logger.getLogger(MyService.class)
  RemoteProviderWrapper remoteProviderWrapper = new RemoteProviderWrapper()
  void shakyServiceMethod(String parameter){
    try{
      remoteProviderWrapper.callRemoteProvider(parameter)
    }catch(RemoteProviderCommunicationException e){
      log.error "Communication failure with external provider: ${e.message}"
      // Do cleanup, rollback transactions, report to the user..
    }
  }
}

Om man tittar vi på vad som händer i själva catch blocket (jag är fullt medveten om att det inte är optimalt att lösta exception hantering på detta sätt, men det är bara ett exempel). Det skrivs ut ett felmeddelande som talar om att det inte går att kommunicera med den externa tjänsten. Denna loggutskrift är guld värd för någon som, utan programmerardjup kunskap om systemet, ska förstå vad som är roten till problemet. Hela systemet kan ju just nu stå och kräkas ur sig stackutskrifter från exceptions. Antagligen finns det en trigger i övervakningssystemet på denna logutskrift. Alltså bör vi testa att detta logmeddelande verkligen kommer ut som en del i vårt testramverk. Jag har skapat en log4j appender som sväljer alla meddelenaden för att senare i en testkod kunna hämta ut dem och verifiera vad de innehåller:

package se.diabol.test.logunit
import org.apache.log4j.AppenderSkeleton
import org.apache.log4j.spi.LoggingEvent
class UnitTestAppender extends AppenderSkeleton { 
  private List messages = []  
  protected void append(LoggingEvent event) {    
    messages += event.renderedMessage  
  }  
  void close() {}  
  boolean requiresLayout() {return false}  
  String[] getMessages() {
    return messages as String[]
  }
  void clear() {
    messages = []
  }
}

Ok, nu har vi en appender, då är det bara att tala om för log4j att den ska användas (sätter det på root loggern här)

log4j.rootCategory=DEBUG, junittestappender
log4j.appender.junittestappender=se.diabol.test.logunit.UnitTestAppender

Därefter kan man skriva ett unittest som använder appendern för att verifiera loggningen som sker i koden.

package se.diabol.test.logunit

import org.junit.Test
import groovy.mock.interceptor.*
import org.apache.log4j.LogManager

class MyServiceTest {
    @Test
    void makeFailedCallToRemoteProvider(){
        def appender = LogManager.rootLogger.getAppender("junittestappender")
        appender.clear()

        def mock = new MockFor(RemoteProviderWrapper.class)
        mock.demand.callRemoteProvider { throw new RemoteProviderCommunicationException("Communication link down!")}
        mock.use{
            new MyService().shakyServiceMethod("Test parameter")
        }

        assert appender.messages == ["Communication failure with external provider: Communication link down!"]
    }
}

Jag börjar med att hämta ut den appender som log4j har skapad och tömmer eventuella gamla meddelanden “clear()”. Sen använder jag grooys inbyggda mockningsfunktionalitet för att skapa en mockad “RemoteProviderWrapper”. Denna mock kommer skicka ett “RemoteProviderCommunicationException” varje gång den anropas. Innanför “mock.use{” blocket kommer alla försök att skapa en “RemoteProviderWrapper” returnera den mock jag angivit ovanför. Jag behöver alltså inte tala om för MyService att den ska använda den mockade klassen på något annat sätt. Sen anropar jag service metoden “shakyServiceMethod”. När det är gjort, hämtar jag ut allt som lagrats i test appendern och verifierar att en logutskrift verkligen skett.
Vad var nu sysftet med detta? Jo, plötsligt har blicken lyfts lite. Här finns en tanke om att det inte bara är själva koden som är viktigt. Denna kod sitter antagligen i någon modul som ingår i ett system. För modulen och programmeraren är loggningen helt irrelevant. Men för systemet och verksamheten kan det vara fråga om skillnader i timmars felsökning för att hitta en extern tjänst som gått ner, eller se ett korrekt felmeddelande i övervakningssystemet. Det är vad utveckling för driftbarhet handlar om.
Nästa steg är att även involvera nämnt övervakningssystem i systemutvecklingen och börja göra automatiska funktionstester som även omfattar övervakning.