Události v aplikaci - II

Tento článek navazuje na předchozí příspěvek Události v aplikaci – I.

Události

Pokud jste někdy přišli do styku s komunikací přes message broker s využitím vzoru publish-subscribe, pak vám systém aplikačních událostí ve Spring bude jistě hodně blízký.

V podstatě úlohu message brokeru v tomto případě plní Spring kontext.

Témata se nespecifikují explicitně. Tématem a událostí zároveň může být instance třídy odvozená od společného předka ApplicationEvent.

V novějších verzích Spring už není stanoven ani tento požadavek, a událostí může být instance libovolné třídy. Já ale preferuji odvození událostí od společného předka, protože na první pohled vidíte, k čemu je definovaná třída určená.

Společný předek všech aplikační událostí ApplicationEvent je abstraktní třída, která zahrnuje dva atributy:

• source [Object] – objekt, ve kterém vznikla událost (při vytvoření instance události se obvykle nastavuje na this, ale nemusí to tak vždy být)

• timestamp [long] – čas vzniku události uvedený v milisekundách

Vzhledem k tomu, že ApplicationEvent je abstraktní třída, není možné použít instanci této třídy jako událost (ona ta instance nejde ani vytvořit). Musíte si udělat vlastní hierarchii tříd od ní odvozených, která bude reprezentovat vaše události.

Jednu takovou jsem si vytvořil i já v rámci přípravy tohoto článku (opět pro přehlednost nejdříve schéma):

Výchozí třídou pro všechny mé události je CustomEvent. Nemá žádné atributy, jen jednu metodu getEvent(), která vrátí název události jako řetězec poskládaný s názvů tříd v dědické linii (výsledek uvidíte později).

Dále mám vytvořeny další dvě třídy ProviderEvent a ApplicantEvent. Ty budou reprezentovat události vzniklé v poskytovateli služeb, resp. v klientovi. Obě třídy mají definovány tyto atributy:

• phase [Phase] – fáze zpracování požadavku (proč tady je se pokusím vysvětlit dále)

• request [Request] – požadavek na službu

• response [Response] – výsledek služby

Každá událost sebou může nést, a taky obvykle nese, doplňující údaje k ní se vztahující. V případě ProviderEvent jsou to objekty reprezentující požadavek a výsledek služby. Dle mého názoru je dobré těmito údaji nešetřit, mohou se vám při reakci na událost hodit.

A teď se ještě vrátím k atributu phase, a co tím vlastně chci ukázat.

Jakým způsobem přistoupit k definici typu událostí, které mohou vznikat v mé aplikaci?

1. Prvním přístupem který se nabízí, je vytvořit celou hierarchickou strukturu tříd odpovídající všem typům událostí. Je to dobrý přístup, jen se nám může stát, že těch událostí, a k nim definovaných tříd bude velké množství (třeba desítky nebo stovky dle rozsahu aplikace a míry sledování událostí).

2. Druhou možností, a asi dost extrémní z druhé strany, je vytvoření pouze jedné třídy reprezentující všechny vaše události. Ty se pak nebudou rozlišovat podle třídy, ale nastavením jednotlivých atributů.

3. No a poslední možností, kterou právě naznačují atributem phase, je kombinace obou výše uvedených přístupu. Do jisté úrovně rozlišuji události definicí tříd. Detailnější rozlišení je pak pomocí atributu.

V diagramu jsou zachyceny ještě dvě třídy reprezentující aplikační události – SupervisionEvent a DelayedCustomEvent. K nim se detailněji dostanu v dalších kapitolách. V tomto okamžiku bude postačovat konstatování, že tam jsou.

Při definici událostí a hierarchie tříd je potřeba také brát do úvahy, jak asi budeme chtít na události reagovat. Zda budeme na některé typy událostí reagovat stejně nebo obdobně. Ale k tomu blíže až v kapitolách zabývající se reakcí na události.

Oznámení vzniku události

Oznámení vzniku události je velice triviální a bylo vidět již v předchozích ukázkách implementace poskytovatele služby nebo klienta.

Takto nějak to vypadá v implementaci poskytovatele:

@Autowired private ApplicationEventPublisher publisher;

@Override
public ResponseA perform(RequestA request) {

    ...

    publisher.publishEvent(new ProviderEvent(this, ProviderEvent.Phase.ASKED, request));

    ...
}

Pro publikování potřebujeme objekt implementující rozhraní ApplicationEventPublisher. V našem případě je to jednoduché, neboť takový objekt poskytuje Spring kontext. Stačí udělat injektáž přes anotaci @Autowire.

No a pak na tomto objektu zavolat metodu publishEvent() s parametrem instance události.

A to je vše.

Na tomto místě, jak nás učí vzor publish-subscribe, neřešíme, zda na událost někdo reaguje a případně jakým způsobem. To je úkolem někoho jiného.

Reakce na událost

K čemu by nám bylo oznamování vzniku událostí, pokud bychom na ně nebyli schopni reagovat. V následujících kapitolách se podívám na možnosti, jak reagovat na vznik událostí a co s daty, které v rámci události jsou k dipozici. Výčet jistě nebude konečný. Vždy bude záviset na vaší aplikaci, co a kdy chcete při jejím běhu sledovat.

Pokud chci zachytit vznik nějaké události, potřebuji splnit dvě podmínky:

1. Mít nějaký objekt s metodou anotovanou @EventListener.

2. Metoda musí mít jeden parametr třídy odvozené od ApplicationEvent.

Anotací Spring kontextu sděluji, že je metoda určená pro reakci na aplikační události. Třídou parametru se pak specifikuje, jaký typ události má být metodou zpracován (to je jako byste se v případe komunikace publish-subscribe přihlásili k odebírání zpráv z určitého tématu).

Každý z dále uvedených příkladů reakce na událost je zahrnut do samostatného profilu. Proto pokud jej chcete vyzkoušet, musíte při startu zadat tento profil jako aktivní.

Všechny třídy, které implementují metody pro zpracování událostí, jsou umístěny do package listener.

Zápis události to logu

Asi to nejjednodušší, co bychom mohli s události udělat, je zápis do logu. Zde je tedy takový příklad pro zápis o vzniku události ProviderEvent a ApplicantEvent:

@Service
@Profile("listener-simple")
public class SimpleEventListener {

    private static final Logger logger = LoggerFactory.getLogger(SimpleEventListener.class);

    @EventListener
    @Order(10)
    public void handleApplicantEvent(ApplicantEvent event) {
        logger.info("Applicant Event handled: {} by {} at {}",
                StringUtils.rightPad(event.getPhase().toString(), 10),
                event.getSource().getClass().getSimpleName(),
                new SimpleDateFormat("HH:mm:ss").format(new Date(event.getTimestamp())));
    }

    @EventListener
    @Order(10)
    public void handleProviderEvent(ProviderEvent event) {
        logger.info("Provider Event handled:  {} by {} at {}",
                StringUtils.rightPad(event.getPhase().toString(), 10),
                event.getSource().getClass().getSimpleName(),
                new SimpleDateFormat("HH:mm:ss").format(new Date(event.getTimestamp())));
    }
}

Třída je anotovaná jako @Service, takže při startu budu mít ve Spring kontextu jednu její instanci.

Dále mám definovány dvě metody, jedna pro obsluhu události typu ApplicantEvent a druhá pro ProviderEvent. Do logu pak mohu zapsat i údaje, které si vytáhnu z instance události (to je ta instance, kterou jsem předal při volání publishEvent().

Jak si to mohu zkusit

Nejdříve si pustím server s profilem:

[raska@fedora jv-application-events-guide]$ java -jar target/application-events-guide-1.0.0.jar --spring.profiles.active=listener-simple

Dále pak z jiného příkazového řádku vyvolám službu:

[raska@fedora ~]$ jo -p nid=local:node02 name=node02 tid=${RANDOM} value=20 | curl -s -X GET --data-binary @- -H "Content-type: application/json" http://localhost:8080/rest/serviceA | jq .
{
  "nid": "local:node01",
  "name": "node01",
  "tid": "8062",
  "ts": "2021-12-12T09:19:14.885+00:00",
  "code": "OK",
  "result": 21
}

Terminál se spuštěným serverem by měl vypisovat něco takového:

2021-12-12 10:19:14.885  INFO 3233 --- [nio-8080-exec-1] c.d.a.listener.SimpleEventListener       : Provider Event handled:  ASKED      by ServiceProviderA at 10:19:14
2021-12-12 10:19:14.885  INFO 3233 --- [nio-8080-exec-1] c.d.a.listener.SimpleEventListener       : Provider Event handled:  ANSWERED   by ServiceProviderA at 10:19:14

Výpis události jako JSON objekt

V případě, že by vás zajímaly všechny informace, které si sebou nese daná událost, můžete si je vypsat do logu například jako JSON objekt. A to dělá právě tato třída:

@Service
@Profile("listener-json")
public class JsonEventListener {

    private static final Logger logger = LoggerFactory.getLogger(JsonEventListener.class);

    @Autowired private ObjectMapper objectMapper;

    @EventListener
    @Order(20)
    public void handleEvent(CustomEvent event) {
        try {
            logger.info("Custom Event {} handled: JSON DATA: \n{}", event.getClass().getSimpleName(), objectMapper.writerWithDefaultPrettyPrinter().writeValueAsString(event));
        } catch (JsonProcessingException e) {
            logger.error("Object to JSON mapping failed!", e);
        }
    }
}

Chtěl bych upozornit na jednu věc, a sice typ parametru event. V tomto případě je event definován jako abstraktní předek CustomEvent. To znamená, že bude přijímat všechny události, které jsou od něj odvozeny.

A ještě jedna poznámka, která se týká anotace @Order. Metod, které mohou přijmout a zpracovat konkrétní událost, může být několik. Obecně není specifikováno, v jakém pořadí se budou provádět. V případě, že vám záleží na tom, v jakém pořadí se boudou metody volat, můžete použít právě tuto anotaci. Parametrem je pořadí … čím menší číslo, tím výše v pořadí metoda bude.

Jak si to mohu zkusit

Opět si spustím server a přidělím mu dva profily, listener-simple a listener-json:

[raska@fedora jv-application-events-guide]$ java -jar target/application-events-guide-1.0.0.jar --spring.profiles.active=listener-simple,listener-json

Dále pak z jiného příkazového řádku vyvolám službu:

[raska@fedora ~]$ jo -p nid=local:node03 name=node03 tid=$RANDOM text=blablabla | curl -s -X GET --data-binary @- -H "Content-type: application/json" http://localhost:8080/rest/serviceB | jq .
{
  "nid": "local:node01",
  "name": "node01",
  "tid": "28188",
  "ts": "2021-12-12T08:59:50.836+00:00",
  "code": "OK",
  "text": "text length: 9"
}

Terminál se spuštěným serverem by měl vypisovat něco takového:

2021-12-12 09:59:50.755  INFO 5276 --- [nio-8080-exec-1] c.d.a.listener.SimpleEventListener       : Provider Event handled:  ASKED      by ServiceProviderB at 09:59:50
2021-12-12 09:59:50.835  INFO 5276 --- [nio-8080-exec-1] c.d.a.listener.JsonEventListener         : Custom Event ProviderEvent handled: JSON DATA:
{
  "source" : {
    "instanceName" : "Provider B"
  },
  "timestamp" : 1639299590748,
  "phase" : "ASKED",
  "request" : {
    "nid" : "local:node03",
    "name" : "node03",
    "tid" : "28188",
    "ts" : "2021-12-12T08:59:50.740+00:00",
    "text" : "blablabla"
  },
  "response" : null,
  "event" : "CustomEvent.ProviderEvent.ASKED"
}
2021-12-12 09:59:50.838  INFO 5276 --- [nio-8080-exec-1] c.d.a.listener.SimpleEventListener       : Provider Event handled:  ANSWERED   by ServiceProviderB at 09:59:50
2021-12-12 09:59:50.840  INFO 5276 --- [nio-8080-exec-1] c.d.a.listener.JsonEventListener         : Custom Event ProviderEvent handled: JSON DATA:
{
  "source" : {
    "instanceName" : "Provider B"
  },
  "timestamp" : 1639299590838,
  "phase" : "ANSWERED",
  "request" : {
    "nid" : "local:node03",
    "name" : "node03",
    "tid" : "28188",
    "ts" : "2021-12-12T08:59:50.740+00:00",
    "text" : "blablabla"
  },
  "response" : {
    "nid" : "local:node01",
    "name" : "node01",
    "tid" : "28188",
    "ts" : "2021-12-12T08:59:50.836+00:00",
    "code" : "OK",
    "text" : "text length: 9"
  },
  "event" : "CustomEvent.ProviderEvent.ANSWERED"
}

Vidíte, že nejdříve mám záznamy ze třídy SimpleEventListener následované záznamy z JsonEventListener.

Dále bych chtěl ještě upozornit na atribut event, který je vytvořen na základě názvů tříd hierarchie událostí v kombinaci a dalšími atributy.

Dlouhé zpracování události

Nejdříve si zkuste tohle a pak až vysvětlím, co se to vlastně děje.

Takže nejdříve spustit server s profilem listener-long:

[raska@fedora jv-application-events-guide]$ java -jar target/application-events-guide-1.0.0.jar --spring.profiles.active=listener-long

A dále pak zavolat službu:

[raska@fedora ~]$ time jo -p nid=local:node03 name=node03 tid=$RANDOM text=blablabla | curl -s -X GET --data-binary @- -H "Content-type: application/json" http://localhost:8080/rest/serviceB | jq .
{
  "nid": "local:node01",
  "name": "node01",
  "tid": "16211",
  "ts": "2021-12-12T09:17:19.990+00:00",
  "code": "OK",
  "text": "text length: 9"
}

real    0m10.502s
user    0m0.042s
sys     0m0.015s

Odpověď jsem dostal v pořádku, ale proč to trvalo tak dlouho?

Když se podíváte na implementaci metody, bude to asi zřejmé:

@Service
//@EnableAsync
@Profile("listener-long")
public class LongLastingEventListener {

    private static final Logger logger = LoggerFactory.getLogger(LongLastingEventListener.class);

//    @Async
    @EventListener
    @Order(30)
    public void handleEvent(ProviderEvent event) {
        logger.info("Provider Event started ...");
        try {
            Thread.sleep(5000);
        } catch (InterruptedException e) {
            logger.error("Exception occurred", e);
        }
        logger.info("Provider Event finished ...");
    }
}

Metoda nedělá nic podstatného, pouze zastaví provádění na 5 sekund.

To, že se nám to pozastavení promítlo do celkové doby zpracování služby znamená, že reakce na události se běžně zpracovávají ve stejném vláknu jako kód, který událost vytvořil (zpracování událostí je synchronní s vytvářením).

To ale obvykle nechceme. Nechceme, aby sledování běhu našeho systému přímo ovlivňovalo efektivitu poskytování jeho služeb.

Z toho plyne následující:

Pokud připravujete reakce na události, které mohou konzumovat nezanedbatelný čas, je vždy dobré je udělat jako asynchronní.

A proto jsou v implementaci zakomentovány dvě anotace, a sice @EnableAsync u třídy a @Async u metody.

Zkuste je odkomentovat, sestavit projekt a spustit znovu. Pak by váš výsledek měl vypadat daleko lépe:

[raska@fedora ~]$ time jo -p nid=local:node03 name=node03 tid=$RANDOM text=blablabla | curl -s -X GET --data-binary @- -H "Content-type: application/json" http://localhost:8080/rest/serviceB | jq .
{
  "nid": "local:node01",
  "name": "node01",
  "tid": "12410",
  "ts": "2021-12-12T09:29:51.737+00:00",
  "code": "OK",
  "text": "text length: 9"
}

real    0m0.562s
user    0m0.038s
sys     0m0.019s

Jen ještě upozorním na výpisy, které se dělají při reakci na událost:

2021-12-12 10:29:51.753  INFO 6195 --- [         task-1] c.d.a.listener.LongLastingEventListener  : Provider Event started ...
2021-12-12 10:29:51.765  INFO 6195 --- [         task-2] c.d.a.listener.LongLastingEventListener  : Provider Event started ...
2021-12-12 10:29:56.754  INFO 6195 --- [         task-1] c.d.a.listener.LongLastingEventListener  : Provider Event finished ...
2021-12-12 10:29:56.766  INFO 6195 --- [         task-2] c.d.a.listener.LongLastingEventListener  : Provider Event finished ...

Z časů je vidět, že doba zpracování je stále těch 5 sekund.