Loguri și metrici în Java

Vasile Mihali
Senior Software Engineer @ Arobs

Suntem într-o formă mai mare sau mai mică dependenți de loguri - aceasta este realitatea. Scopul acestui articol nu este să prezint o anumită tehnologie Java de logare ci nivele superioare de abstractizare pentru colectarea, memorarea și analiza lor. De asemenea, intenția este de a prezenta cum acestea ne ajută pentru a avea o privire de ansamblu mai clară asupra ceea ce se întâmplă în aplicația/aplicațiile noastre dacă logăm informații cu sens și un scop clar definit în utilizarea lor.

Dar ce sunt aceste loguri și de ce avem nevoie de ele? Un mesaj de log este un mic punct, dar mai multe astfel de puncte înseamnă o linie, liniile, o formă sau o direcție care trebuie interpretată. Menționăm mai jos și alte trăsături:

• Starea lor e constantă, nu se modifică.

• Sunt sute de mii, milioane pe zi -numărul lor depinde de natura aplicației, de utilizarea sistemelor adiționale pentru auditarea ei, precum și de prezența aplicațiilor complexe.

• Durata de viață de după creare e relativ scurtă: 30 de zile, 6 luni sau poate chiar mai mult pentru sistemele financiare sau care conțin informații mai sensibile. Depinde din nou de natura aplicației, de linia de business care o acoperă și dacă se folosesc sisteme adiționale pentru auditare - după care pot ajunge să fie menținute în mod pasiv în arhive, etc..

În aplicațiile monolitice gruparea logurilor se face de obicei pe zile i.e. JBoss filename+".yyyy-MM-dd iar analiza lor este de cele mai multe ori anevoioasă, fiind necesare cunoștințe destul de avansate în expresii regulare și comenzi Linux sau scripturi de Python, Scala, etc.. De asemenea, aplicațiile sunt rulate în general de servicii de hosting private (cloud), iar conectarea din exterior necesară preluării acestor fișiere de log, care pot să aibă o mărire considerabilă chiar și arhivate, devine consumatoare de timp. La acestea se adaugă și o îngreunare a procesului de analiză. Astfel că de cele mai multe ori, nu sunt analizate decât atunci când cineva începe să se plângă de o problemă, când sistemul nu mai răspunde cu aceeași viteza solicitărilor sau când o greșeală se repetă pentru o durată de timp îndelungată. Ori în cazul extremis - nu mai funcționează.

Img. Load-balancer/proxy (tutorialspoint.com)

Chiar și în aplicați monolitice începem să observăm sisteme adiacente aplicației noastre (proxy-uri, load-balance) care la rândul lor au loguri care conțin informații importante despre modul în care e folosită aplicația, atacuri de securitate, timpi de răspuns, etc..

Dar ce e de făcut atunci când trecem aplicațiile pe arhitectură descentralizată i.e. micro-services? Cum colectăm atunci aceste loguri de pe fiecare mașină în parte? Cum facem legătura între aceste loguri acolo unde este necesar, cât de ușor puteam realiza acest lucru?

Arhitectură micro-service (tigerteam.dk)

Dacă prelucrăm aceste loguri doar atunci când lucrurile merg prost, s-ar putea, în unele cazuri, să fie prea târziu. De aceea, sunt de părere că o analiză continuă a lor e imperios necesară în fazele de validare, staging. Acest demers se impune și în primele luni de după punerea în producție sau cel puțin până când lucrurile devin stabile. Calitatea de stabil depinde de fiecare funcționalitate / produs / politică a companiei / contract de mentenanță încheiat, etc.. Chiar și în faza de dezvoltare putem avea beneficii dacă urmărim anumite informații/metrici din aceste loguri.

Să nu neglijăm importanța a ceea ce conțin logurile generate de aplicație . Conținutul lor aduce valență pozitivă prin informații care pot fi de ajutor în procesele următoare.

Aici avem libertatea deplină asupra conținutului și putem să ni-l personalizăm cum dorim - recomand totuși folosirea unui template de logare în proiect/module. Întrucât foarte multe aplicații Java enterprise au și module de procesare, migrări de date, task-uri asincron, rapoarte, etc. care nu îți oferă un feedback direct (cum se întâmplă cu un request web) atunci aceste informații devin vitale pentru a putea garanta și cunoaște dacă sistemul funcționează corect.

Soluția aplicată de noi - și nu doar de noi pentru că este o soluție foarte populară și des folosită:

1. ELK (Elastic, Logstash (+ loggregator), Kibana)

Img.Logs - Pipeline (blog.xebia.fr - Vincent S.)

Proces:

1. Aplicațiile folosesc appender-ul pentru consolă (log4j + slf4j) - stdout.

2. De aici folosim loggregator (CloudFoundry) - agent care preia stream-ul de date de la stdout.

3. Logstash primește logurile, le procesează (ETL, transformare date în formate generice, etc.).

4. Logurile sunt indexate apoi în Elastic.

5. Folosim Kibana pentru a le afișa.

Astfel se creează un sistem centralizat de loguri a tuturor aplicațiilor/modulelor care deservesc aceluiași scop, cu formate de loguri comune, aceleași formatări de date, decupare de text ce poate fi ignorant, precum și alte îmbunătățiri pentru a le face mai ușor de urmărit, corelat și interpretat.

2. Metrics. Core Metrics.

Librăria de la CodaHale e una dintre cele mai populare librării de metrici folosită în aplicații open source de succes (Cassandra).

Aceasta pune la dispoziție un registru:

Logger log = LoggerFactory.getLogger(MetricsUtils.class);
MetricRegistry metrics = new MetricRegistry();
Slf4jReporter reporter = Slf4jReporter.forRegistry(metrics)
       .outputTo(log)
       .convertRatesTo(TimeUnit.SECONDS)
       .convertDurationsTo(TimeUnit.MILLISECONDS)
       .build();

care e ulterior folosit de către:

1.counter

Counter failedMigrationSessions = metrics.counter(
   MetricRegistry.name(Entity.class, 
   “migration-sessions-failed”));

2.histograme

Histogram migrationSizes = metrics.
  histogram(MetricRegistry.name(MigrationUtilsImpl. 
    class, “migration-sizes”));

3.timer

Timer migrationTimer = metrics.timer(MetricRegistry.name(MigrationUtilsImpl.class, "migration-timer"));

4.altele - care nu intră în scopul acestui articol.

  Apeluri ale metodelor:

public void incIdsToMigrate(long d) {

        migrationSizes.update(d);
}

public void incFailedMigrationSessions() {
        failedMigrationSessions.inc();
}

//migration util class
@Override
public Response migrate(String entityCanonicalName, List idSToMigrate) {

final Timer.Context context = MetricsUtils.getInstance().getMigrationTimer().time();
final MigrationSession migrationSession = 
     new MigrationSession(entityCanonicalName, 
      idSToMigrate.size());
try {

… //validation, others
MetricsUtils.getInstance().incIdsToMigrate(idSToMigrate.size());
….
} finally {
       context.stop();
       if (migrationSession.isGeneralError()) {
                MetricsUtils.getInstance().
        incFailedMigrationSessions();
       }
}

Loguri:

[MetricsUtils.info:110] type=TIMER, name=com....MigrationUtilsImpl.migration-timer, count=463, min=14185.432459, max=120866.415675, mean=48638.78311404348, stddev=33618.49316878979, median=33732.338869, p75=68521.92468899999, p95=120788.85010139999, p98=120866.415675, p99=120866.415675, p999=120866.415675, mean_rate=0.0023544359078945367, m1=2.964393875E-314, m5=2.2626576149598838E-82, m15=4.532485314583121E-30, rate_unit=events/second, duration_unit=milliseconds

[MetricsUtils.info:108] type=HISTOGRAM, name=com…..MigrationUtilsImpl.migration-sizes, count=463, min=4, max=35, mean=19.541666666666668, stddev=12.021644127831763, median=19.5, p75=33.75, p95=35.0, p98=35.0, p99=35.0, p999=35.0

[MetricsUtils.info:104] type=COUNTER, name=com….MigrationUtilsImpl.migration-sessions-failed, count=0

Totodată analiza zilnică/săptămânală a logurilor și corelarea lor cu valori lunare într-o aplicație sau serviciu web și nu numai, ne poate ajuta să monitorizăm starea actuală precum și evoluția aplicației sau cum e folosită pentru a putea răspunde proactiv la noi provocări.

[LoggingFilter.filter:100] 13bd85d2-1464-406a-70ee-99ef10545989 - method=GET code=200 url=workbases - Round trip response duration=25 millis
[LoggingFilter.filter:100] 084f6732-8824-4311-7d3d-d8596f8bfc43 - method=GET code=200 url=workbases - Round trip response duration=29 millis
[LoggingFilter.filter:100] 71ddc0fa-281f-4f80-6664-1374aa14b0c2 - method=GET code=200 url=registrationruns - Round trip response duration=232 millis
[LoggingFilter.filter:100] ebbf5225-7800-46b9-5e1c-bfec7d25dec1 - method=GET code=200 url=registrationruns - Round trip response duration=318 millis
[LoggingFilter.filter:100] cb721bc3-adea-4bfd-708d-8f8a7c39c9aa - method=POST code=201 url= registrationruns - Round trip response duration=5 millis

Acest tip de loguri ne permit să menținem astfel de statistici:

Concluzii:

Trecerea de la aplicații monolitice la arhitecturi distribuite aduce flexibilitate și noi provocări. Una dintre ele e modul în care se realizează logarea, modul cum le salvăm și accesăm. Un aspect important îl are și calitatea informațiilor pe care le logăm. Știm că loguri precum "Save'< entity >'" nu aduc prea mult sens. Astfel trebuie să ne asigurăm ca logăm acele informații "prețioase" care au sens în timp și ne ajută să înțelegem modul în care e utilizat sistemul, precum și performanța actuală a acestuia sau necesitățile viitoare.

O continuă monitorizare a logurilor, corelarea lor poate să ne dea o nouă viziune asupra cum putem îmbunătăți un sistem sau cât de stabil îl putem face. Condiții de bază într-un sistem distribuit sunt vizibilitatea pe care noi o avem asupra a ceea ce se întâmplă și monitorizarea logurilor. Numai așa vom avea posibilitatea să reacționam la variații ( a timpilor de răspuns, a numărului de itemuri procesate pe minut ) care sunt primul semn că nu avem un sistem stabil.