W tej serii poruszę fundamentalny temat, który dotyczy znakomitej większości systemów IT. Tematem będzie... czas, a ściślej to, w jaki sposób informacja o aktualnym czasie powinna być dostarczana do logiki biznesowej i innych elementów oprogramowania, które wytwarzamy.
Dawno temu, niestety w tej galaktyce
Parę lat temu zostałem zatrudniony, żeby postawić na nogi pewien projekt. Według pierwotnych oszacowań projekt ten miał trwać rok, ale kiedy się za niego zabrałem miał już dwa lata opóźnienia. Ilość błędów architektonicznych i personalnych w tym przedsięwzięciu przerosła moją wyobraźnię kilkukrotnie, a wierzcie mi wyobraźni mi nie brakuje. Jedno z kolejnych rozczarowań, którego doznałem niedługo po tym, jak zostałem odpowiedzialny za uratowanie tego projektu, jest bezpośrednią inspiracją do napisania tego cyklu.
Otóż był drugi stycznia pewnego roku. Wszedłem do biura i siadając do swojego biurka odruchowo rzuciłem okiem na wielki ekran, na którym prezentowana była informacja o statusie testów automatycznych poszczególnych mikroserwisów systemu. Na ekranie wszystko było czerwone. Zaskoczyło mnie to, gdyż kiedy ostatni raz byłem w biurze, tj. 31 grudnia, ekran był zielony niczym trawa na boisku piłkarskim.
Pomyślałem oczywiście, że ktoś w międzyczasie wrzucił do repo kod, który wprowadził masę błędów regresji. Zapytałem więc chłopców co się stało, kto tak spektakularnie rozpoczął nowy rok. Wskazali winowajcę, ale od razu też dodali, że ich zdaniem to nie zmiany z ostatniego commita stały za tą sytuacją, że przyczyna musiała być inna. W projekcie było ponad pięćset testów, a około sto pięćdziesiąt z nich właśnie przestało przechodzić. Po krótkiej analizie okazało się, że to efekt nowego roku, a nie zmian w kodzie źródłowym. Cofnięcie zegara o dwa dni w tył sprawiało bowiem, że znów wszystkie testy kończyły się powodzeniem.
Okazało się, że w kodzie źródłowym pełno jest wywołań metody LocalDateTime.now() i że architektura systemu nie przewidywała żadnej możliwości podmockowania źródła czasu. Ze względu na dramatyczne opóźnienie projektu i liczne inne problemy, nie mieliśmy możliwości poprawienia architektury dostarczania aktualnego czasu do systemu. Jedynym akceptowalnym, choć żenującym, wyjściem z tej sytuacji było przejście przez każdy ze stu pięćdziesięciu testów i... dostosowanie go do aktualnego roku - byliśmy boleśnie świadomi, że testy te za rok znów wybuchną.
Poprawki niestety nie zawsze były oczywiste, wymagały dużej uwagi i były ryzykowne (nic bowiem nie jest bardziej ryzykowne w projekcie niż modyfikacja testów; po takiej modyfikacji testy mogą bowiem być już niewiele warte - w końcu przecież nikt nie pisze testów weryfikujących testy... prawda?). Tak więc najlepszy z inżynierów utonął na trzy dni w wielkim i bardzo nieprzyjemnym refactoringu. Drugi najlepszy inżynier przez te trzy dni przeglądał merge requesty pierwszego. Reszta zespołu próbowała ciągnąć projekt dalej, ale ponieważ ogromna liczba testów nie przechodziła, na trzy dni straciliśmy informację zwrotną o tym, czy równolegle nanoszone zmiany w kodzie źródłowym nie wprowadzają do systemu błędów regresji.
Jak zwykle błąd, w tym wypadku architektoniczny, przekłada się na realne straty. Tutaj dwóch najlepszych inżynierów w pocie czoła i pod ogromną presją czasu wykonywało parszywe (inaczej nie da się tego określić) zadania refactoringu testów. Ich frustracja była ogromna. Ci inżynierowie, zamiast pchać projekt do przodu, przez trzy dni wydobywali go z zapaści. Nastroje w zespole były minorowe. Wszyscy bowiem czuli, że coś jest fundamentalnie nie tak z ich systemem. Nowy rok zaczął się nam naprawdę nieprzyjemnie.
Na czym polegał błąd? Otóż na tym, że poprzez wielokrotne wywołania metody LocalDateTime.now() w kodzie produkcyjnym, testy stały się zależne od aktualnego czasu systemowego środowiska, w którym były uruchamiane. Była to jednak tylko konsekwencja znacznie poważniejszego problemu - architektura całego rozwiązania nie dawała bowiem możliwości podmockowania źródła czasu i sterowania tym źródłem w testach. Dochodzimy tutaj do bardzo jednoznacznej reguły, której nie należy łamać:
W kodzie źródłowym może znajdować się maksymalnie jedno* wywołanie dowolnej z następujących metod i konstruktorów: LocalDate.now(), LocalDateTime.now(), System.currentTimeMillis(), new Date() itp., a także dodatkowo, maksymalnie jedno wywołanie metody System.nanoTime().
*Istnieje pewna okoliczność, która rozluźnienia tę regułę dopuszczając maksymalnie dwa wywołania wymienionych metod i konstruktorów. Później, znacznie później, wyjaśnię o co chodzi.
Problem jest nadal żywy
Ludzkość wytwarza soft już od ponad pól wieku, a jednak wciąż na nowo powtarza te same błędy. Zdumiewa mnie to..., ale tak jest.
Oto jakiś czas temu (było to parę lat po wyżej opisanej sytuacji) miałem okazję przyjrzeć się architekturze pewnego dużego systemu. Odnotowałem, że w systemie tym nie ma żadnej abstrakcji dla funkcjonalności pobierania aktualnego czasu - w kodzie pełno było wywołań metody LocalDateTime.now().
Na spotkaniu z architektem tego systemu przedstawiłem Mu wszystkie moje wnioski z przeglądu jego dzieła. Jednym z nich było wskazanie na problem braku abstrakcji dla pobierania aktualnego czasu. Wyjaśniłem, że konsekwencją braku takiej możliwości jest uzależnienie testów od aktualnego czasu systemowego środowiska, w którym takie testy są uruchamiane, co dalej będzie prowadziło do regularnego załamywania się tych testów (jak we wcześniej opisanym przypadku), a także całkowicie uniemożliwi testowanie niektórych funkcjonalności systemu. Niestety głuchym na moje argumenty okazał się ten architekt. Los jednak bywa złośliwy...
Otóż kilka dni po naszej rozmowie, w kodzie tego systemu znalazłem taki oto fragment, który mnie zaintrygował:
@PreUpdate
void setAuditInfo(Auditable auditable) {
Audit audit = auditable.getAudit();
audit.setLastUpdatedDateTime(LocalDateTime.now().minusYears(3));
audit.setLastUpdatedBy(getUserName());
}Moją uwagę zwrócił fragment minusYears(3). Skontaktowałem się z autorem tego kodu, żeby zapytać jakie biznesowe uzasadnienie ma w tym wypadku odjęcie trzech lat od aktualnego czasu i... dlaczego odejmujemy akurat trzy lata, a nie np. pięć. Odpowiedź wprawiła mnie w osłupienie. Usłyszałem, że kod ten został wcommitowany... przez przypadek. Jedynie na potrzeby testów, bo nie było możliwe zrobienie tego w inny sposób, autor tego kodu dodał fragment minusYears(3) i niestety zapomniał tę zmianę wycofać przed wykonaniem commita. Prawidłowa postać tego kodu powinna była wyglądać tak:
@PreUpdate
void setAuditInfo(Auditable auditable) {
Audit audit = auditable.getAudit();
audit.setLastUpdatedDateTime(LocalDateTime.now());
audit.setLastUpdatedBy(getUserName());
}Zgroza! Ten developer nie musiałby, na potrzeby testów, modyfikować ciała metody setAuditInfo gdyby tylko w architekturze systemu istniała warstwa abstrakcji nałożona na funkcjonalność pobierania aktualnego czasu - niestety takiej warstwy nie było.
Spójrzmy na przykład
Wyobraźmy sobie, że w tworzonym przez nas systemie mamy zaimplementować tablicę ogłoszeń. Tworzymy więc klasę o nazwie Announcement, która wśród wielu różnych pól będzie zawierała takie oto trzy:
1. publicationDateTime - czas opublikowania ogłoszenia
2. timeToLive - czas, przez jaki ogłoszenie ma być publikowane
3. message - treść ogłoszenia
Zaczynamy więc pisać kod. Pierwsze linijki wyglądają tak:
public final class Announcement
{
private final LocalDateTime publicationDateTime;
private final Duration timeToLive;
private final String message;
// Pozostałe pola pominięte ze względu na zwięzłość
// to be continued...
}Do naszej klasy dodajemy konstruktor (zwróć uwagę na linijkę kodu wyróżnioną kolorem pomarańczowym):
public final class Announcement
{
private final LocalDateTime publicationDateTime;
private final Duration timeToLive;
private final String message;
// Pozostałe pola pominięte ze względu na zwięzłość
public Announcement(final Duration timeToLive, final String message)
{
if ( timeToLive == null )
throw new IllegalArgumentException();
if ( timeToLive.isNegative() || timeToLive.isZero() )
throw new IllegalArgumentException();
if ( (message == null) || message.isEmpty() )
throw new IllegalArgumentException();
this.publicationDateTime = LocalDateTime.now();
this.timeToLive = timeToLive;
this.message = message;
}
// to be continued...
}Jak widzisz za datę i czas publikacji ogłoszenia uznano moment stworzenia obiektu. Cóż.... pewnie w bardziej dojrzałym systemie użytkownik miałby możliwość ustawienia daty i czasu publikacji ogłoszenia (na przykład po to, aby takie ogłoszenie zostało opublikowane w przyszłości), ale to jest system pisany naprędce, w ciasnych terminach więc... nie mamy czasu na lukrowanie funkcjonalności. Ogłoszenie jest widoczne natychmiast po jego stworzeniu. Koniec. Kropka.
To, co jest istotne, to fragment kodu, który pobiera czas - jest to nieszczęsna, niemockowalna metoda now() z klasy LocalDateTime. Stworzy to nam pewne problemy w testach, ale do tego dojdziemy za chwilę.
Napisaliśmy walidacje argumentów wejściowych, ale po wnikliwej lekturze dokumentacji analitycznej odkryliśmy, że czas, przez jaki ogłoszenie ma być publikowanie, nie powinien być krótszy niż jedna godzina. Dodajemy więc takie oto trzy linijki kodu.
public final class Announcement
{
private static final Duration MIN_TIME_TO_LIVE = Duration.ofHours(1);
private final LocalDateTime publicationDateTime;
private final Duration timeToLive;
private final String message;
// Pozostałe pola pominięte ze względu na zwięzłość
public Announcement(final Duration timeToLive, final String message)
{
if ( timeToLive == null )
throw new IllegalArgumentException();
if ( timeToLive.isNegative() || timeToLive.isZero() )
throw new IllegalArgumentException();
if ( timeToLive.compareTo(MIN_TIME_TO_LIVE) < 0 )
throw new IllegalArgumentException();
if ( (message == null) || message.isEmpty() )
throw new IllegalArgumentException();
this.publicationDateTime = LocalDateTime.now();
this.timeToLive = timeToLive;
this.message = message;
}
// to be continued...
}Nasz klasa posiada również metodę isExpired(), która zwraca informację o tym, czy minął już czas, przez jaki ogłoszenie miało być publikowane. Metoda ta jest zaimplementowana następująco:
public boolean isExpired() {
final boolean result;
final LocalDateTime now = LocalDateTime.now();
final LocalDateTime expirationDateTime =
publicationDateTime.plus(timeToLive);
result = expirationDateTime.compareTo(now) <= 0;
return result;
}Napisanie testów tej metody (dokładnych testów) jest niemożliwe. Jedyne, co możemy zrobić, to napisać testy przybliżone. Nie mamy bowiem możliwości zamockowania źródła czasu.
Na marginesie dodam, że niektórym, takie przybliżone testy nie będą przeszkadzały - tych nazywam developerami. Będą jednak i tacy, którzy z powodu tego przybliżenia nie będą mogli spać - tych nazywam inżynierami. Interesuje mnie praca tylko i wyłącznie z tymi drugimi - developerom dziękuję. Nie zatrudniam takich, a kiedy już przez przypadek takie indywiduum znajdzie się w moim zespole to prędzej czy później z niego... wypada.
No ale przejdźmy do napisania naszego testu. Pierwsze linijki są oczywiste.
public class AnnouncementTest {
@Test
void isExpired() {
final Duration announcementTimeToLive = Duration.ofHours(1);
final Announcement announcement =
new Announcement(announcementTimeToLive, "irrelevant");
assertFalse(announcement.isExpired());
// to be continued...
}
}Co robi powyższy kod? Tworzy obiekt, klasy Announcement, którego czasu publikacji ma trwać jedną godzinę. Następnie sprawdza czy ogłoszenie reprezentowane przez ten obiekt wygasło. Test ten odbywa się natychmiast po utworzeniu obiektu, czyli na dłuuugo przed jego wygaśnięciem - oczekujemy więc, że metoda isExpired() zwróci tutaj false.
Teraz dopiero zaczyna robić się ciekawie. Musimy bowiem sprawdzić, czy metoda isExpired() w ogóle kiedykolwiek zwraca wartość inną niż false. Oczekujemy bowiem, że po upływie godziny zwróci true. Z ciężkim sercem piszemy taki oto kod, który efektywnie uśmierci nasz test - nikt nigdy nie będzie chciał go wykonać.
public class AnnouncementTest {
@Test
void isExpired() throws InterruptedException {
final Duration announcementTimeToLive = Duration.ofHours(1);
final Announcement announcement =
new Announcement(announcementTimeToLive, "irrelevant");
assertFalse(announcement.isExpired());
TimeUnit.HOURS.sleep(1); // godzina czekania, porażka!
assertTrue(announcement.isExpired());
}
}To jednak nie koniec tej smutnej historii. Po namyśle dochodzimy do wniosku, że nasz test jest bardzo niedokładny. Co prawda potwierdza, że po kilku nanosekundach, od utworzenia obiektu klasy Announcement, metoda isExpired() zwraca false, a po upływie godziny zwraca true, to jednak nie mamy pewności, czy na skutek błędu, metoda ta nie zwraca true już po np. 30 minutach? W idealnym świecie chcielibyśmy zrobić taki oto test:
wywołać metodę isExpired() na chwilę przed spodziewanym momentem wygaśnięciem ogłoszenia
wywołać metodę isExpired() idealnie w spodziewanym momencie wygaśnięcia ogłoszenia
wywołać metodę isExpired() chwilę po spodziewanym momencie wygaśnięcia ogłoszenia
Co rozumiem przez "chwilę"? Najmniejszą możliwą jednostkę czasu rozróżnianą przez klasy LocalDateTime i Duration - jest nią nanosekunda.
Niestety jednak nie da się tego zrobić. Załóżmy bowiem, że przerobimy nasz kod na taki:
public class AnnouncementTest {
@Test
void isExpired() throws InterruptedException {
final Duration announcementTimeToLive = Duration.ofHours(1);
final Announcement announcement =
new Announcement(announcementTimeToLive, "irrelevant");
assertFalse(announcement.isExpired());
TimeUnit.MINUTES.sleep(59);
TimeUnit.SECONDS.sleep(59);
TimeUnit.NANOSECONDS.sleep(999_999_999);
// W tym momencie, z całą pewnością jesteśmy już dalej niż
// o jedną godzinę od chwili wywołania LocalDateTime.now()
// w konstruktorze klasy Announcement
assertFalse(announcement.isExpired()); // na 100% zwróci true
TimeUnit.NANOSECONDS.sleep(1);
assertTrue(announcement.isExpired());
}
}Dlaczego w chwili drugiego wywołania assertFalse(announcement.isExpired()) jesteśmy już w punkcie czasu dalszym niż jedna godzina liczona od chwili pobrania aktualnego czasu w konstruktorze klasy Announcement? Oto dlaczego:
kilka nanosekund zajęło wykonanie pozostałych dwóch operacji przypisania w konstruktorze klasy Announcement
kilka kolejnych nanosekund zajęło wirtualnej maszynie wyjście z tego konstruktora
kilka kolejnych nanosekund zajęło pierwsze wywołanie assertFalse(announcement.isExpired())
itd., itd., itd. - masakra... nie do obliczenia, a nawet gdyby ktoś wykazał się odpowiednim uporem, żeby to policzyć, to wynik zmieni się po przeniesieniu tego kodu na inny procesor (szach, mat)
Do tego uwzględnij jeszcze wpływ wywłaszczenia wątków Javy na rdzeniach procesora przez inne wątki (np. pochodzące z systemu operacyjnego) i.... już widzisz sam, że przekroczyliśmy granicę oddzielającą inżynierię od magii, gdzie zamiast obliczeń pozostaje nam zgadywanie. Najlepszy test, jaki możemy napisać będzie wyglądał tak:
public class AnnouncementTest {
@Test
void isExpired() throws InterruptedException {
final Duration announcementTimeToLive = Duration.ofHours(1);
final Announcement announcement =
new Announcement(announcementTimeToLive, "irrelevant");
assertFalse(announcement.isExpired());
TimeUnit.MINUTES.sleep(59);
TimeUnit.SECONDS.sleep(55);
// zostawiamy 5-sekundowy margines bezpieczeństwa
assertFalse(announcement.isExpired());
TimeUnit.SECONDS.sleep(5);
assertTrue(announcement.isExpired());
}
}Ten test, nie dość, że będzie się wykonywał przez godzinę, to jeszcze jest niedokładny - dla przykładu: nie jest w stanie wykryć zmiany warunku mniejszy lub równy na mniejszy, w metodzie isExpired(). Tak więc dla mnie ten test jest nic niewarty. Zwyczajnie nie można na nim polegać.
To jak to wszystko zrobić właściwie?
Naprawdę chętnie udzieliłbym odpowiedzi na to pytanie tu i teraz. Niestety jednak narzędzie informuje mnie, że czas czytania tego artykułu wynosi już osiem minut i jeżeli dopiszę jeszcze kilka wyrazów nikt tego artykułu już nie przeczyta. Tak więc, zapraszam Cię drogi czytelniku do kolejnej części tej serii - jest dostępna tutaj.
"One more thing..."
Ten i inne artykuły piszę po to, żeby podzielić się swoją wiedzą i doświadczeniem z innymi. Jednakże napisanie artykułu to dopiero połowa sukcesu - drugą połowę stanowi dotarcie z treścią do innych. Możesz mi bardzo pomóc w tym zadaniu - wystarczy, że klikniesz w jedną z czterech ikon poniżej i udostępnisz innym link do tego posta. Za tę pomoc będę Ci bardzo wdzięczny.