Logs sind die Rettung

Bei New Relic nutzen wir in großem Umfang Application Performance Monitoring (APM), um unsere eigenen Dienste zu überwachen und zu optimieren. APM sammelt relevante Metriken und Traces, um Serviceprobleme zu identifizieren und zu diagnostizieren. Aber leider ist es selbst für uns unmöglich, alles, was wir wissen wollen, im Voraus zu instrumentieren. Die Instrumentierung für eine Untersuchung oder nach einem Incident ist zwar eine gute Praxis, aber was ist, wenn Sie Ihr Problem sofort anhand der Daten lösen möchten, die Sie bereits haben?

Logs sind die Rettung!

Was ist das Tolle an Logs?

In eine Datei geschriebener unstrukturierter Text ist möglicherweise die älteste Form der Telemetrie. Programme spucken seit den Anfängen der modernen Computertechnik Text aus. Diese Allgegenwärtigkeit ist die erste Superkraft von Logs. Selbst wenn andere Informationen fehlen, hat wahrscheinlich jemand ein Log gesendet, das sagt, was los ist.

Logging ist inzwischen so weit verbreitet, dass die Standardbibliotheken für viele Sprachen direkt über integrierten Logging-Support verfügen. Für Umgebungen ohne Standard-Logger gibt es fast immer solide und flexible Alternativen von Drittanbietern. Darüber hinaus gibt es viele Tools zum Formatieren, Steuern, Erfassen und Interpretieren Ihrer Logs im gesamten Stack.

Was ist an Logs weniger toll?

Erinnern Sie sich an das Wort „unstrukturiert“? Das ist der Knackpunkt bei Logs als Telemetrietyp. Aufgrund ihres historisch bedingten Textschwerpunkts können Logs als Auffangbehälter für Krimskrams enden, der ohne Konsistenz oder Planung zusammengewürfelt wird. Verglichen mit der klaren Bedeutung eines Metrikwerts oder dem bekannten Schema und den Beziehungen für Trace-Spans sind Logs chaotisch.

Was die fehlende Struktur zusätzlich verkompliziert, ist die Tatsache, dass Sie möglicherweise nicht kontrollieren können, wie die Logs formatiert werden, die Ihnen am wichtigsten sind. Unabhängig davon, ob es sich um Ihren Webserver oder Ihren Cloudanbieter handelt, könnte für einen Teil dieses kritischen Outputs hinsichtlich Format und Inhalt die Parole gelten: „Nehmen Sie, was Sie bekommen können“.

Logs können zudem riesig sein. Die Tatsache, dass sie so einfach zu generieren sind, kann dazu führen, dass jede Ebene des Stacks eine enorme Textflut auslöst. Wenn Sie nicht aufpassen, kann das Debug-Logging sogar lokale Anwendungsprobleme verursachen, wenn auf den Festplatten nicht mehr genügend Speicherplatz vorhanden ist. Das Erfassen, Speichern und Abfragen dieser riesigen Datenmengen kann eine Herausforderung sein.

Wie können Sie Logs effektiver nutzen?

Wie können Sie angesichts dieser Stärken und Schwächen Ihr Logging verbessern und das Beste aus diesem Datentyp herausholen? Wir beleuchten ein paar New Relic Logging-Features, damit Sie sehen, wie Logs Ihnen Einblicke liefern können, die über die herkömmliche, uns allen vertraute Instrumentierung hinausgehen.

Strukturiertes Logging

Ich habe Logs mit einem Auffangbehälter verglichen. Aber das heißt nicht, dass Ihr Behälter mit Krimskrams vollgestopft sein muss. Wenn Logs aus einer Anwendung unter Ihrer Kontrolle stammen, können Sie die Vorteile des strukturierten Logging nutzen, um das Ganze zu bändigen.

In der gängigsten Form bringen wir Klarheit in unsere Logs, indem wir JSON-Daten anstelle von Rohtextzeilen ausgeben. Das JSON kann Standardattribute haben, die bei der späteren Verarbeitung helfen. Anstatt also ein Log wie dieses zu haben …

… sehen Sie beispielsweise all dies beim Versuch herauszufinden, was denn eigentlich passiert ist:

Oft lässt sich eine solche Logformatierung in Ihr Web-Framework integrieren, sodass Sie nicht einmal zusätzliche Werte festlegen und den JSON-Code nicht selbst erstellen müssen. Tolle Beispiele hierfür in der Rails-Welt sind lograge und semantic_logger.

Logs mit anderen Daten in Beziehung setzen

Mit der Möglichkeit, unseren Logs Struktur und Bedeutung zu verleihen, wird es jetzt einfacher, mit ihnen in einem zentralen System zu arbeiten, sei es ein lokaler ELK-Stack (Elasticsearch, Logstash und Kibana) oder ein Software-as-a-Service(SaaS)-Anbieter wie New Relic. Für Anwendungsentwickler:innen ist das Filtern in ihrer Anwendung nach Logs der erste Schritt, um die Nadeln im Heuhaufen zu finden.

Alle New Relic APM Agents verfügen über integrierte Log-Forwarding-Funktionen, die automatisch Metadaten hinzufügen, um nicht nur die Anwendung, sondern auch Traces und Spans (also einzelne Anfragen in Ihrem System) zu verknüpfen. Damit können Sie beispielsweise die Logs einsehen, die zu einem bestimmten Fehler-Trace generiert wurden.

Wenn Ihnen der Stack-Trace und andere Merkmale des Fehlers nicht alles verraten, können diese Logs die benötigten Einblicke liefern.

Nicht jedes Unternehmen möchte das APM Agent Forwarding verwenden. Es kann beispielsweise sein, dass Sie bereits eine Log-Forwarding-Lösung verwenden, die in Ihrem Kubernetes-Cluster oder mit einem zentralen Syslog-Server konfiguriert ist. Auch wenn Ihre Logs über etwas anderes als den APM Agent versandt werden, können Sie von dieser umfassenden Verknüpfung von Logs und APM profitieren, und zwar durch die Option „Local Decoration“, wörtlich das lokale Ausschmücken von Logs. Wenn diese Option aktiviert ist, werden die geschriebenen Logs so geändert, dass sie über die erforderlichen Metadaten verfügen, um alle Vorzüge der Logverknüpfung in der New Relic UI zu erhalten.

Logs parsen

Aber was ist, wenn Ihre Logs zwar nicht als JSON formatiert sind, stattdessen aber nützliche Zahlen im Text versteckt sind? Einige unserer Java-Apps verfügen beispielsweise über interne „Service“-Klassen mit einem eigenen Lebenszyklussystem, das Lognachrichten wie diese erstellt:

Die Zeitinformationen am Zeilenende wären als Metrik oder Event sehr hilfreich, aber sie sind leider nur in den Lognachrichten vergraben. Wir können jedoch immer noch das Gesuchte abfragen.

In diesem Fall beginnen wir damit, die Zeilen, die uns interessieren, über die Logging-UI zu finden, die die Suche nach Stichwörtern und einfachen Attributwertpaaren erleichtert. Neben der Schaltfläche „Query logs“ befindet sich die Schaltfläche „NRQL“ (New Relic Query Language), und hier wird es interessant. Wenn Sie darauf klicken, wird der Query Builder geöffnet. Hier sehen Sie die NRQL-Abfrage, die zum Suchen nach der aktuellen Loggruppe verwendet wurde:

Wir haben jetzt nach den Nachrichten gefiltert, die uns wichtig sind, und können daher den Nachrichtentext mit einer der neueren Funktionen von NRQL untersuchen: aparse. Ich will hier nicht noch einmal die Dokumentation wiederholen, aber für die obige Nachricht können wir aparse wie folgt verwenden, um die Zeitinformationen zu extrahieren:

Sehr schön! Dadurch erhalten wir nun in unserem Ergebnis ein Attribut mit dem Namen startupDuration. Wir benötigen auch den Namen der Klasse. Dazu nutzen wir aparse in einem WITH-Block:

Jetzt sehen wir eine Tabelle mit Services und den dazugehörigen Zeitinfos. Versuchen wir mal, das für ein paar Funktionen zu nutzen! Wir gruppieren nach service und ermitteln den Durchschnittswert von startupDuration , um zu sehen, wie jede Klasse abschneidet:

Leider erscheint in der Spalte für den Durchschnittswert nichts. Warum das? Denken Sie daran, wir befinden uns im Land der Logs – alles ist Text! Ein kurzer Funktionsaufruf kann das jedoch für uns beheben.

Für eine langfristige Nutzung lohnt es sich, diese Daten als echte Metrik aufzuzeichnen – entweder direkt in der Anwendung oder über das New Relic Events-to-Metrics-Feature. Alternativ könnte man eine Parsing-Regel erstellen, die den Wert bei der Erfassung der Daten in ein eigenes Attribut extrahiert und so die spätere Abfrage erleichtert.

So oder so können wir unsere Arbeit heute mit den Logs erledigen, die wir bereits haben. Und da es sich bei diesen Logs einfach nur um NRDB-Daten handelt, können Sie diese Ergebnisse auch anderswo in New Relic verwenden, z. B. für Alerts, Dashboards oder zum Definieren von Service Level Objectives (SLOs).

Logs im Zeitverlauf korrelieren

Hier ist ein letzter Trick, um Ihnen zu zeigen, was beliebige Logs und NRQL alles können. Angenommen, wir sind wie zuvor an der Startdauer unserer Anwendung interessiert. Allerdings sind die Zeiten dieses Mal nicht in einer einzelnen Zeile eingebettet. Stattdessen haben wir zwei Zeilen, zwischen denen wir die Zeitspanne ermitteln möchten: eine, als die App gestartet wurde, und eine spätere, als die Traffic-Erfassung begann.

Veranschaulichen möchten wir Ihnen das an einem Beispiel vom Logging-Team von New Relic selbst! Wenn unser primärer Datenerfassungsservice hochfährt, erhalten wir zwei verschiedene Zeilen:

• In der ersten Zeile sehen wir starting log-parser-consumer; das zeigt an, dass die Java-Anwendung gestartet wurde.
• Die zweite ruft den Klassennamen für unseren Kafka Consumer auf (LogsToParseKafkaConsumerAutoService) und teilt uns mit, dass er ausgeführt wird.

Wir beginnen mit der Erstellung einer Abfrage, um die entsprechenden Zeilen und sonst nichts zu finden. Das sieht ungefähr so aus:

Als nächstes benötigen wir ein eindeutiges Datenelement – etwas, das bei jedem Anwendungsstart unterschiedlich ist. New Relic verwendet strukturiertes Logging. Damit erhalten wir einen eindeutigen pod_name, der für diesen Zweck perfekt ist. Diese nächste Abfrage zielt darauf ab, die beiden Nachrichten, die uns wichtig sind, nach Pod gruppiert anzuzeigen. Eine Spalte erhält die Startnachricht und die andere die Endnachricht:

Wir können sehen, dass dies mit dem Gesuchten übereinstimmt: Für jeden pod_name werden die beiden Zeilen hier in einer Zeile angegeben:

Die latest-Funktion in NRQL kennen Sie vielleicht noch nicht. Dies ist eine Aggregatfunktion, die genau das tut, was sie verspricht: Sie übernimmt aus dem Dataset den aktuellsten Wert. Hier sehen wir uns die message an, aber nachdem wir uns überzeugt haben, dass es funktioniert, konzentrieren wir uns auf das, was wir eigentlich suchen: latest(timestamp). Damit können wir die Start- und Endzeitstempel berechnen. Und voilà, wir haben Zeitdaten zwischen zwei beliebigen Punkten in unserem Log-Stream!

Fazit

Wenn Sie etwas Numerisches messen möchten, ist eine Metrik möglicherweise die beste Wahl. Aber wenn Ihnen nur noch Logs übrig bleiben, ist das auch keine Katastrophe! Im Logging-Team von New Relic haben wir die oben beschriebenen Tricks mehrfach angewendet, um neue relevante Performance-Daten zu ermitteln, Fehlerquellen leicht zu lokalisieren und Verbesserungen bei Alerts und Monitoring voranzutreiben. Ihre Logs können Ihrem System neue Transparenz verleihen, also fangen Sie an mit dem Logging!