Loki - Slimme logs en event centralisatie bij Avisi Cloud

Iedere eigenaar van een Cloud Platform, DevOPS of SR engineer, functioneel beheerder én eindgebruiker weet dat op complexe platformen geregeld events en incidenten plaatsvinden. Hier spreken we bijvoorbeeld over (deels) gefaalde backups, applicaties die ongepland unresponsive worden, verdachte inlogpogingen of plotselinge performance degradatie van infrastructuur of tooling. Goed inzicht in events die applicaties loggen is essentieel om falende componenten binnen korte tijd up and running te krijgen, en het liefst geautomatiseerd. Ook is het essentieel om in de analyse fase tot root causes te komen van eventuele problemen en om zo structurele oplossingen te vinden die het platform stabieler maken en eindgebruikers een betere ervaring geven. Goede beschikbaarheid, toegankelijkheid en inzichtelijkheid in onze infrastructuur en applicaties is wat we willen en nodig hebben! In deze blog zoomen we in op één van de belangrijkste OPS-taken die ieder verstandig DevOps-team moet inregelen om controle te houden over de stabiliteit van een groeiend Cloud-platform: het inzichtelijk maken van logging en events.

Grafana Loki Log Exploring

Avisi Managed Environments

Het inzichtelijk maken van logging en events. Hoe doen we dit? Voordat we hier dieper op ingaan, gaan we het eerst hebben over AME (Avisi Managed Environments). Binnen Avisi heeft Team Cloud een volautomatisch platform (zie: Avisi Managed Environments) ontwikkeld. Hiermee kunnen klanten hun bedrijfskritische software in een volwaardig Cloud environment hosten met alle bijkomende voordelen en flexibiliteit die de Cloud biedt. Veel uitdagingen, die komen kijken bij de uitrol van High Available Cloud clusters (Kubernetes), worden door AME uit handen genomen. We hebben het hier niet alleen over het deployen van de clusters, maar ook over het inregelen van zaken als security, software updates, schaalbaarheid en monitoring & alerting. Dit zijn typische OPS-aandachtspunten, waarvan logging en events een erg belangrijke is. 

Troubleshooting & logging

De standaard flow bij het afhandelen van (bijvoorbeeld) een applicatie outage of een melding van performance degradatie verloopt als volgt:

1. Een ticket of automatische alert komt binnen. Snel wordt de aard van het probleem helder gemaakt;
2. Tijdstip waarop het probleem, voor het eerst, optrad wordt achterhaald;
3. Op welk cluster het probleem speelde/speelt wordt bepaald;
4. Key metrics van het betreffende cluster worden verzameld, zoals uptime applicaties/tools, systeem load, CPU-gebruik, memory-gebruik, database-connecties en responstijden;
5. Logging van rond het tijdstip van de verstoring wordt verzameld. 

Om Key Metrics van het betreffende cluster te verzamelen wordt Grafana in combinatie met Prometheus gebruikt. Prometheus is een veelgebruikte monitoring-oplossing binnen Cloud en Kubernetes environments om time-series data te verzamelen over systemen, databases en applicaties. Grafana kan deze data visualiseren in grafieken.

Grafana Prometheus Metrics monitoring

Mensen zijn goed in het herkennen van patronen. Uit bovenstaande grafieken blijkt wanneer en waar het probleem, zoals een verhoging in systeem load, voor het eerst optrad. In een Cloud-setting kan bijvoorbeeld het killen van een falende Kubernetes pod de aangewezen manier om de klant up-and-running te krijgen. Echter, iedere OPS Engineer wil naast een (near-)100% uptime de root-cause van een probleem achterhalen om soortgelijke problemen in de toekomst te voorkomen. Dit pinpointen kan vaak niet zonder beschikbaarheid van logging die inzicht geeft in wat een applicatie of infrastructuurcomponent precies doet en op welk tijdstip. De logging dus die zojuist verdwenen is met de pod die je gekilled hebt  

Wat we willen is een centraal systeem dat doorlopend al onze decentrale systeem- en applicatie-logging gestructureerd opslaat. Bij AME gebruiken we voor het aggregeren en visualiseren van al onze relevante logging de open-source stack: Promtail -> Loki <- Grafana. 

Wat is Loki?

In de glanzende folder bij het Loki-project staat eenvoudig uitgelegd wat de Loki stack is: "Loki is a horizontally-scalable, highly-available, multi-tenant log aggregation system inspired by Prometheus." Niet meteen een pakkende tekst die je neefje van 5 over de streep gaat trekken, tenzij je een bijzonder getalenteerd neefje hebt dat erg weinig buiten speelt maar het klinkt ingewikkelder dan het is. Een wat meer uitgebreide variant: 

Loki is een tool, waarmee we alle door onze Kubernetes-clusters gegenereerde systemen en applicatie logging kunnen centraliseren ("log aggregation system") op bijvoorbeeld een AME beheerserver. 

Qua opzet is Loki gedeployed als (Kubernetes) microservices. Dit betekent dat de verschillende componenten waaruit Loki bestaat niet in een monolitisch blok software draaien, maar ieder component afzonderlijk zijn taak vervult in een eigen pod die afzonderlijk te tunen is. Dit maakt Loki eenvoudig schaalbaar in een groeiend serverfarm ("horizontally-scalable") en hoog beschikbaar ("highly-available"). Zo kun je er voor kiezen om niet één maar drie Loki 'querier' componenten naast elkaar te draaien, die vervolgens de zoekopdrachten van users gezamenlijk afhandelen. Als één van de queriers gepland of ongepland down gaat, vangen de andere queriers de traffic op tot het issue gefixt is. Verder is Loki in staat om logstromen vanuit verschilllende organisaties strikt gescheiden op te slaan en te houden ("multi-tenant"). Last but not least: Loki is nauw verwant aan Prometheus ("inspired by Prometheus") die de al eerdergenoemde metrics (zie stap vier) beschikbaar stelde in Grafana. Dit laatste is erg handig. Het zorgt ervoor dat je met één visualisatie-oplossing, zoals Grafana, zowel metrics als logging naast elkaar kunt tonen binnen een specifiek timespan.

Prometheus Metrics en Loki logging in één Grafana window

Hoe slaat Loki logregels gestructureerd op?

In tegenstelling tot enkele belangrijke alternatieven voor Loki (zoals Elastic stack en Splunk), werkt Loki niet met inverted text indexes waarbij afzonderlijke woorden met verwijzingen in grote indexes worden opgeslagen. Inverted text indexes zijn zeer geschikt om te gebruiken in zoekmachine-technologie en resulteren bij vrije tekst-zoekopdrachten in extreem snelle resultaten op je scherm. Een belangrijk voordeel van inverted text indexes is dus snelheid. De trade-off is echter hoge resource-eisen door grote indexes, denk aan memorygebruik en storage-eisen als dure SSD voor goede performance. Loki kiest bewust voor een resource vriendelijkere benadering en slaat zijn logregels op in verschillende "log streams" (op goedkope S3 storage). Loki probeert zijn zoeksnelheid vooral op te krikken door slim te paralleliseren.

Bijvoorbeeld:
Dit is een logregel gegenereerd door een container en via Promtail agent verzonden naar Loki: 

ts=2020-08-25T16:55:42.986960888Z caller=spanlogger.go:53 org_id=29 traceID=2612c3ff044b7d02 method=Store.lookupIdsByMetricNameMatcher level=debug matcher="pod=\"loki-canary-25f2k\"" queries=16

2020-08-25T16:55:42.987

{job=“loki-canary”,namespace=“loki”,pod=“loki-canary-25f2k”,container=“canary”}

ts=2020-08-25T16:55:42.986960888Z caller=spanlogger.go:53 org_id=29 traceID=2612c3ff044b7d02 method=Store.lookupIdsByMetricNameMatcher level=debug matcher="pod=\"loki-canary-25f2k\"" queries=16

De eerste regel toont de timestamp van de logregel. Daarnaast wordt logregel metadata in de vorm van labels meegezonden en opgeslagen. Promtail, de scrape agent op de endpoints, die logging verzendt naar Loki, is hier verantwoordelijk voor. Als laatste wordt de ruwe logregel zelf opgeslagen.

Metadata in de vorm van labels is handig om later gewenste logging te kunnen filteren en tonen in Grafana. De metadata is voor Loki-indexering echter ook belangrijk, want dit bepaalt in welke "log stream" de logregel opgeslagen zal worden. Iedere unieke combinatie van labels wordt namelijk in een aparte log stream opgeslagen. Dit vraagt om een bepaalde benadering en afwegingen bij het inrichten van de log flow. Een voorbeeld:

11.11.11.11 - frank [25/Jan/2000:14:00:01 -0500] "GET /1986.js HTTP/1.1" 200 932 "-" "Mozilla/5.0 (Windows; U; Windows NT 5.1; de; rv:1.9.1.7) Gecko/20091221 Firefox/3.5.7 GTB6"

11.11.11.12 - frank [25/Jan/2000:14:00:02 -0500] "POST /1986.js HTTP/1.1" 200 932 "-" "Mozilla/5.0 (Windows; U; Windows NT 5.1; de; rv:1.9.1.7) Gecko/20091221 Firefox/3.5.7 GTB6"

11.11.11.13 - frank [25/Jan/2000:14:00:03 -0500] "GET /1986.js HTTP/1.1" 400 932 "-" "Mozilla/5.0 (Windows; U; Windows NT 5.1; de; rv:1.9.1.7) Gecko/20091221 Firefox/3.5.7 GTB6"

11.11.11.14 - frank [25/Jan/2000:14:00:04 -0500] "POST /1986.js HTTP/1.1" 400 932 "-" "Mozilla/5.0 (Windows; U; Windows NT 5.1; de; rv:1.9.1.7) Gecko/20091221 Firefox/3.5.7 GTB6"

11.11.11.15 - erik [25/Jan/2000:14:00:05 -0500] "GET /1986.js HTTP/1.1" 200 932 "-" "Mozilla/5.0 (Windows; U; Windows NT 5.1; de; rv:1.9.1.7) Gecko/20091221 Firefox/3.5.5 GTB6"

Stel dat promtail geconfigureerd is om deze http logging te parsen en een "action" label (key/value) te extraheren (dus: "action=GET", "action=POST") en een status code te extraheren: (dus: "status_code=200", "status_code=400"), dan leidt dit tot de volgende streams in storage:

{job=”apache”,env=”dev”,action=”GET”,status_code=”200”}
11.11.11.11 - frank [25/Jan/2000:14:00:01 -0500] "GET /1986.js HTTP/1.1" 200 932 "-" "Mozilla/5.0 (Windows; U; Windows NT 5.1; de; rv:1.9.1.7) Gecko/20091221 Firefox/3.5.7 GTB6"
{job=”apache”,env=”dev”,action=”GET”,status_code=”200”} 11.11.11.15 - erik [25/Jan/2000:14:00:05 -0500] "GET /1986.js HTTP/1.1" 200 932 "-" "Mozilla/5.0 (Windows; U; Windows NT 5.1; de; rv:1.9.1.7) Gecko/20091221 Firefox/3.5.5 GTB6"

{job=”apache”,env=”dev”,action=”POST”,status_code=”200”}
11.11.11.12 - frank [25/Jan/2000:14:00:02 -0500] "POST /1986.js HTTP/1.1" 200 932 "-" "Mozilla/5.0 (Windows; U; Windows NT 5.1; de; rv:1.9.1.7) Gecko/20091221 Firefox/3.5.7 GTB6"

{job=”apache”,env=”dev”,action=”GET”,status_code=”400”}
11.11.11.13 - frank [25/Jan/2000:14:00:03 -0500] "GET /1986.js HTTP/1.1" 400 932 "-" "Mozilla/5.0 (Windows; U; Windows NT 5.1; de; rv:1.9.1.7) Gecko/20091221 Firefox/3.5.7 GTB6"

{job=”apache”,env=”dev”,action=”POST”,status_code=”400”}
11.11.11.14 - frank [25/Jan/2000:14:00:04 -0500] "POST /1986.js HTTP/1.1" 400 932 "-" "Mozilla/5.0 (Windows; U; Windows NT 5.1; de; rv:1.9.1.7) Gecko/20091221 Firefox/3.5.7 GTB6"

De vijf bovenstaande logregels zullen door Loki in vier aparte streams worden opgeslagen omdat er vier verschillende key/value combinaties van geëxtraheerde labels bestaan. Te veel verschillende streams creëren in Loki is niet wenselijk en gaat ten koste van performance. Best practice is dus om het aantal label combinaties en daarmee het aantal streams in storage te beperken. Bovenstaande voorbeeld zal waarschijnlijk tot redelijk acceptabele hoeveelheden log streams leiden, omdat het aantal actions en status_codes in HTTP logging doorgaans beperkt is. Wat je met Loki echter absoluut niet moet doen is velden extraheren van bijvoorbeeld het type "IP_adres" of "Referentie_ID" Dit zijn velden die in potentie alleen maar unieke values bevatten, waardoor iedere logregel in een aparte log stream (!) opgeslagen zal worden. In Elastic of Splunk kan dit prima, in Loki is dit door designkeuzes breaking.

Architectuur Loki stack

Loki draait zelf, zoals eerder genoemd, op een centrale server in microservices architectuur.

Componenten zijn individueel verticaal te schalen. Denk aan het toekennen van extra memory of CPU aan bijvoorbeeld een Ingester die verantwoordelijk is voor het wegschrijven van binnenkomende logging in storage. Tevens kunnen Loki-componenten horizontaal geschaald worden. Het is dus eenvoudig om bijvoorbeeld een extra querier component bij te plaatsen wanneer te veel bevragingen vanuit Grafana zorgen voor overbelasting van de bestaande setup. Afhankelijk van de specifieke use-case kan een passende Loki deployment worden neergezet en geschaald wanneer eisen veranderen. 

Logging visualiseren en filteren met LogQL

We hebben onze Loki stack inmiddels draaiend en hebben een kleine historie aan logging opgebouwd. Zinvolle informatie kunnen onttrekken aan onze data is uiteraard waar we het allemaal voor doen. Hiervoor gebruiken we Grafana als GUI en LogQL als query taal.

Werken met LogQL kan in het begin even wennen zijn, maar het helpt als je weet hoe Loki zijn logging opslaat in streams met labels. Deze labels kunnen we mooi gebruiken om onze zoekresultaten te filteren tot een zinvolle set informatie.

Een basis zoekopdracht in een LogQL log query ziet er als volgt uit:

{stream selector} 

Waarbij de stream selector verplicht is en de log pipeline optioneel. Een voorbeeld van een zoekopdracht in Grafana maakt meteen duidelijk hoe het werkt:

{pod="jira-0"}

Dit geeft alle logregels terug die de Jira-applicatie (Jira pod) heeft gegenereerd in de afgelopen vijf minuten. Als we iets specifieker willen zijn en alleen de logging willen zien van de Jira container binnen de Jira-0 pod, dan kunnen we de stream selector aanpassen:

{pod="jira-0", container="jira"}

We zien dat Jira veel logt en we zijn misschien alleen geïnteresseerd in string "error". In dat geval kunnen we een log-pipeline toevoegen op deze manier:

{pod="jira-0", container="jira"} |= "error"

Dit geeft logregels terug die de letterlijke string "error" bevatten in lower case. We zien de "error" strings in de zoekresultaten ook netjes gehighlight worden.

Misschien zijn we bang dat we error-meldingen missen doordat ze gelogd worden in (deels) upper-case. In dat geval kunnen we een eenvoudige regex gebruiken als zoekopdracht die onze string case insensitive maakt:

{pod="jira-0", container="jira"} |~ "(?i)error"

Een regex initieer je met |~ "<regex>"

Het valt buiten de scope van deze blog om uitgebreid op de mogelijkheden van regex in te gaan, maar bovenstaande voorbeeld maakt de string (in dit geval "error") case insensitive. Nu zien we dat er inderdaad meer logregels verschijnen.

We kunnen nog verder gaan met filteren door extra zoektermen toe te voegen aan de bestaande search string. Dit werkt gelijk aan het pipen van commando's in bash. Een voorbeeld: 

{pod="jira-0",container="jira"} |~ "(?i)error" != "INFO"

!= (uitroepteken dus) is een inverse letterlijke search. We willen dus alle regels met case insensitive "error" zien maar niet de logregelen die de letterlijke string "INFO" bevat.

Je kunt vanzelfsprekend zoveel zoektermen (pipes) toevoegen als zinvol is voor je search opdracht.

Wat belangrijk is om in het achterhoofd te houden, is dat het goed gebruik van labels performance ten goede komt. Als je kunt filteren op {namespace="jira", pod="jira-0", container="jira"} dan heeft dit de voorkeur, boven alleen zoeken op het label {container="jira"}. Bij die laatste moet Loki door alle streams zoeken die het key/value pair container=jira bezitten. De kans is aanwezig dat hier een groot aantal streams tussen zitten die niet relevant zijn voor jou als beheerder. Bottom line blijft: labels zijn belangrijk en ga er slim mee om!

Conclusie

De Loki stack is voor Avisi Cloud een logging-oplossing met prima intergratie in bestaande tooling. Het is minimalistisch opgezet, doet één taak en functioneert goed. Het is Kubernetes native, dus gebouwd voor schaalbaarheid. De out-of-the-box deployment van Loki komt met prima defaults die zorgen dat je meteen grote delen van je Kubernetes infrastructuur logging inzichtelijk krijgt met de juiste labels. Loki is in onze praktijk resource vriendelijk gebleken en laat een uitstekende performance zien, zeker in vergelijking met alternatieven. Het leren van LogQL vormt een drempel, maar de absolute basis, zoals in deze blog is getoond, is al voldoende om veruit de meeste use-cases te dekken. 

Door de State-mindset van Cloud Provider Hosts kost het developers veel tijd en handwerk om softwarereleases te doen. Wij van Avisi Cloud vinden dat het uitrollen van software geautomatiseerd moet worden en dat vanuit de Change-mindset gehandeld moet worden. Daarom hebben wij Avisi Managed Environments gecreëerd, waarmee jij 25% extra ontwikkelcapaciteit kan behalen. Wil jij ook 20% extra ontwikkelcapaciteit? Neem dan contact met ons op.