Engineering

Instrumentieren Sie Ihre Go-App mit dem Elastic APM Go Agent

Mit Elastic APM (Monitoring der Anwendungsleistung) erhalten Sie umfassende Einblicke in die Anwendungsleistung und Transparenz für verteilte Arbeitslasten mit offizieller Unterstützung für eine Vielzahl von Sprachen inklusive Go, Java, Ruby, Python und JavaScript (Node.js und Real User Monitoring (RUM) für den Browser).

Um diese Leistungseinblicke zu erhalten, müssen Sie Ihre Anwendung instrumentieren. Beim Instrumentieren ändern Sie den Code Ihrer Anwendung, um deren Verhalten zu messen. Für einige der unterstützten Sprachen reicht es aus, einen Agent zu installieren. Java-Anwendungen können beispielsweise automatisch instrumentiert werden. Setzen Sie dazu einfach das Flag ‑javaagent, das Bytecode-Instrumentierung verwendet, also den kompilierten Java-Code manipuliert, normalerweise beim Laden einer Java-Klasse beim Programmstart. Außerdem ist es üblich, dass ein einziger Thread eine Operation von Anfang bis Ende kontrolliert, um den lokalen Thread-Speicher zum Korrelieren von Operationen verwenden zu können.

Go-Programme werden grob gesagt zu nativem Computercode kompiliert, der sich nicht so leicht automatisch instrumentieren lässt. Außerdem verwenden Go-Programme ein anderes Threadingmodell als die meisten anderen Sprachen. In einem Go-Programm wird Code von einer „goroutine“ ausgeführt, die mehrere Betriebssystem-Threads verwendet, und logische Operationen umfassen oft mehrere goroutines. Wie können wir also Go-Anwendungen instrumentieren?

In diesem Artikel werden wir eine Go-Anwendung mit Elastic APM instrumentieren, um ausführliche Leistungsdaten zu Antwortzeiten (Tracing) sowie Infrastruktur- und Anwendungsmetriken zu erfassen und mit unserem Logging zu integrieren – die drei Grundpfeiler der Observability. Im Verlauf des Artikels werden wir eine Anwendung und deren Instrumentierung erstellen und die folgenden Themen in dieser Reihenfolge behandeln:

Tracing von Webanforderungen

Der Elastic APM Go Agent stellt eine API zum Tracing von Operationen bereit, z. B. für eingehende Anforderungen auf einem Server. Beim Tracing von Operationen werden normalerweise Ereignisse aufgezeichnet, die die Operation beschreiben, z. B. mit Operationsname, Typ/Kategorie und einigen Attributen wie Quell-ID, authentifizierter Benutzer usw. Das Ereignis erfasst außerdem Startzeitpunkt und Dauer der Operation sowie Bezeichner für deren Herkunft.

Der Elastic APM Go Agent stellt zahlreiche Module für die Instrumentierung verschiedener Web-Frameworks, RPC-Frameworks oder Datenbanktreiber sowie für die Integration mit unterschiedlichen Logging-Frameworks bereit. Entdecken Sie die vollständige Liste der unterstützten Technologien.

Wir werden die Elastic APM-Instrumentierung zu einem einfachen Webdienst mit dem gorilla/mux-Router hinzufügen, um Ihnen zu zeigen, wie wir dessen Leistung mit Elastic APM erfassen können.

Hier ist der ursprüngliche Code ohne Instrumentierung:

package main                                                 
import (                                                     
        "fmt"                                                
        "log"                                                
        "net/http"                                           
        "github.com/gorilla/mux"                             
)                                                            
func helloHandler(w http.ResponseWriter, req *http.Request) {
        fmt.Fprintf(w, "Hello, %s!\n", mux.Vars(req)["name"])
}                                                            
func main() {                                                
        r := mux.NewRouter()                                 
        r.HandleFunc("/hello/{name}", helloHandler)          
        log.Fatal(http.ListenAndServe(":8000", r))           
}

Um die vom gorilla/mux-Router verarbeiteten Anforderungen zu instrumentieren, brauchen Sie eine aktuelle Version von gorilla/mux (1.6.1 oder neuer) mit Unterstützung für Middleware. Anschließend können Sie einfach go.elastic.co/apm/module/apmgorilla importieren und die folgende Codezeile hinzufügen:

r.Use(apmgorilla.Middleware())

Damit meldet die apmgorilla-Middleware jede Anforderung als Transaktion an den APM Server. Wir machen jetzt eine kurze Pause von der Instrumentierung und sehen uns das Ergebnis in der APM-Benutzeroberfläche an.

Visualisierung der Leistung

Wir haben unseren Webdienst instrumentiert, aber die Daten werden nirgendwohin gesendet. Die APM-Agents versuchen standardmäßig, ihre Daten an den APM-Server unter http://localhost:8200 zu senden. Wir werden einen frischen Stack mit dem kürzlich veröffentlichten Elastic Stack 7.0.0 einrichten. Sie können das Standarddeployment des Stacks kostenlos herunterladen oder können eine 14-tägige kostenlose Testversion des Elasticsearch Service in der Elastic Cloud starten. Falls Sie eine lokale Lösung verwenden möchten, finden Sie eine Docker Compose-Beispielkonfiguration unter https://github.com/elastic/stack-docker.

Sobald Sie den Stack eingerichtet haben, können Sie Ihre Anwendung für den Versand von Daten an den APM-Server konfigurieren. Dazu benötigen Sie die URL und das geheime Token des APM-Servers. Wenn Sie Elastic Cloud verwenden, finden Sie diese Daten während der Bereitstellung auf der Seite „Activity“ und nach Abschluss der Bereitstellung auf der Seite „APM“. Während der Bereitstellung sollten Sie sich außerdem das Passwort für Elasticsearch und Kibana notieren, da dieses später nicht mehr angezeigt wird (Sie können es jedoch bei Bedarf zurücksetzen).

Elastic APM in der Cloud-Konsole des Elasticsearch Service

Der APM Go Agent wird über Umgebungsvariablen konfiguriert. Um die URL und das geheime Token des APM-Servers zu konfigurieren, exportieren Sie die folgenden Umgebungsvariablen, sodass diese für Ihre Anwendung verfügbar sind:

export ELASTIC_APM_SERVER_URL=https://bdf8658ddda74d47af1875242c3ef203.apm.europe-west1.gcp.cloud.es.io:443
export ELASTIC_APM_SECRET_TOKEN=H9U312SRGzbG7M0Yp6

Wenn wir das instrumentierte Programm jetzt ausführen, sollten nach kurzer Zeit Daten in der APM-Benutzeroberfläche angezeigt werden. Der Agent sendet Metriken in regelmäßigen Abständen: CPU- und Arbeitsspeicherauslastung sowie Go-Laufzeitstatistiken. Für jede verarbeitete Anforderung erfasst der Agent außerdem eine Transaktion. Diese Transaktionen werden zwischengespeichert und standardmäßig alle zehn Sekunden als Batch gesendet. Lassen Sie uns also den Dienst ausführen, einige Anforderungen stellen und sehen, was passiert.

Um herauszufinden, ob die Ereignisse erfolgreich an den APM-Server gesendet werden, können wir die folgenden zusätzlichen Umgebungsvariablen setzen:

export ELASTIC_APM_LOG_FILE=stderr
export ELASTIC_APM_LOG_LEVEL=debug

Starten Sie jetzt die Anwendung (hello.go enthält das Programm, das wir zuvor instrumentiert haben):

go run hello.go

Als nächstes verwenden wir github.com/rakyll/hey, um einige Anforderungen an den Server zu senden:

go get -u github.com/rakyll/hey
hey http://localhost:8000/hello/world

In der Ausgabe der Anwendung sollte in etwa Folgendes angezeigt werden:

{"level":"debug","time":"2019-03-28T20:33:56+08:00","message":"sent request with 200 transactions, 0 spans, 0 errors, 0 metricsets"}

Und in der Ausgabe von hey sollten Sie verschiedene Statistiken sehen, inklusive eines Histogramms mit den Antwortwartezeiten. Wenn wir jetzt Kibana öffnen und zur APM-Benutzeroberfläche navigieren, sollten wir dort einen Dienst mit dem Namen „hello“ und einer Transaktionsgruppe namens „/hello/{name}“ sehen. Mal sehen:

Eine Liste der verfügbaren Dienste in Elastic APM

Drilldown in den „hello“-Dienst in Elastic APM

Vielleicht haben Sie sich dabei einige Fragen gestellt: Woher weiß der Agent, welchen Namen er dem Dienst geben soll, und warum wird das Route-Muster anstelle der Anforderungs-URI verwendet? Die erste Frage ist einfach: Wenn Sie keinen Dienstnamen angeben (mit einer Umgebungsvariable), wird der Name der Binärdatei des Programms verwendet. In diesem Fall ist das Programm in einer Binärdatei namens „hello“ kompiliert.

Das Route-Muster wird verwendet, um Aggregationen zu ermöglichen. Wenn wir die Transaktion anklicken, wird ein Histogramm der Antwortwartezeiten angezeigt.

Antwortwartezeiten in Elastic APM

Achtung: Wir verwenden zwar eine Aggregation über das Route-Muster, aber die komplette URL der Anforderung ist trotzdem in den Transaktionseigenschaften verfügbar.

Tracing von SQL-Abfragen

Typische Anwendungen enthalten eine komplexere Logik und verwenden externe Dienste wie etwa Datenbanken, Caches usw. Für die Diagnose von Leistungsproblemen in Ihrer Anwendung ist es entscheidend, die Interaktionen mit diesen Diensten sehen zu können.

Wir werden uns jetzt ansehen, wie wir die von unserer Go-Anwendung gestellten SQL-Abfragen beobachten können.

Zu Demonstrationszwecken verwenden wir eine eingebettete SQLite-Datenbank, aber sofern Sie mit database/sql arbeiten, ist es egal, welchen Treiber Sie verwenden.

Für das Tracing von database/sql-Operationen stellen wir das Instrumentierungsmodul go.elastic.co/apm/module/apmsql bereit. Das Modul apmsql instrumentiert database/sql-Treiber, um Berichte zu Datenbankoperationen wie etwa spans in einer Transaktion zu erstellen. Um dieses Modul zu verwenden, müssen Sie die Art und Weise ändern, wie Sie den Datenbanktreiber registrieren und öffnen.

Normalerweise importieren Sie in Ihrer Anwendung ein database/sql-Treiberpaket, um den Treiber zu registrieren, z. B.

import _ “github.com/mattn/go-sqlite3” // registers the “sqlite3” driver

Wir stellen verschiedene nützliche Pakete zu diesem Zweck bereit, die jedoch bereits instrumentierte Versionen derselben Treiber registrieren, z. B. für SQLite3, und die Sie stattdessen wie folgt importieren:

import _ "go.elastic.co/apm/module/apmsql/sqlite3"

Hinter den Kulissen wird die Methode apmsql.Register verwendet, die dem Aufruf von sql.Register entspricht, den registrierten Treiber jedoch gleichzeitig instrumentiert. Wenn Sie apmsql.Register verwenden, müssen Sie pmsql.Open anstelle von sql.Open aufrufen, um eine Verbindung zu öffnen:

import (
        “go.elastic.co/apm/module/apmsql”
        _ "go.elastic.co/apm/module/apmsql/sqlite3"
)
var db *sql.DB
func main() {
        var err error
        db, err = apmsql.Open("sqlite3", ":memory:")
        if err != nil {
                log.Fatal(err)
        }
        if _, err := db.Exec("CREATE TABLE stats (name TEXT PRIMARY KEY, count INTEGER);"); err != nil {
                log.Fatal(err)
        }
        ...
}

Wie bereits erwähnt existiert in Go kein lokaler Thread-Speicher wie in vielen anderen Sprachen, mit dem wir verwandte Operationen miteinander verknüpfen können. Stattdessen muss der Kontext explizit weitergegeben werden. Wenn wir mit der Aufzeichnung einer Transaktion für eine Webanforderung beginnen, speichern wir einen Verweis auf die laufende Transaktion im Anforderungskontext, den wir mit der Methode net/http.Request.Context erhalten. Als Demonstration werden wir aufzeichnen, wie oft jeder einzelne Name erschienen ist, und werden die Datenbankabfragen an Elastic APM melden.

var db *sql.DB
func helloHandler(w http.ResponseWriter, req *http.Request) {       
        vars := mux.Vars(req)
        name := vars[“name”]
        requestCount, err := updateRequestCount(req.Context(), name)
        if err != nil {                                             
                panic(err)                                          
        }                                                           
        fmt.Fprintf(w, "Hello, %s! (#%d)\n", name, requestCount)    
}                                                                   
// updateRequestCount erhöht einen Zähler für den Namen in der DB und gibt die neue Anzahl zurück.
func updateRequestCount(ctx context.Context, name string) (int, error) {                                                    
        tx, err := db.BeginTx(ctx, nil)                                                                                     
        if err != nil {                                                                                                     
                return -1, err                                                                                              
        }                                                                                                                   
        row := tx.QueryRowContext(ctx, "SELECT count FROM stats WHERE name=?", name)                                        
        var count int                                                                                                       
        switch err := row.Scan(&count); err {                                                                               
        case nil:                                                                                                           
                count++                                                                                                     
                if _, err := tx.ExecContext(ctx, "UPDATE stats SET count=? WHERE name=?", count, name); err != nil {        
                        return -1, err                                                                                      
                }                                                                                                           
        case sql.ErrNoRows:
                count = 1                                                                                                 
                if _, err := tx.ExecContext(ctx, "INSERT INTO stats (name, count) VALUES (?, ?)", name, count); err != nil {
                        return -1, err                                                                                      
                }                                                                                                           
        default:                                                                                                            
                return -1, err                                                                                              
        }                                                                                                                   
        return count, tx.Commit()                                                                                           
}

Zwei wichtige Hinweise zu diesem Code:

  • Wir verwenden die *Context-Methoden in database/sql (ExecContext, QueryRowContext)
  • Wir übergeben den Kontext aus der umschließenden Anforderung an diese Methodenaufrufe.

Der mit apmsql instrumentierte Datenbanktreiber erwartet einen Verweis auf die laufende Transaktion im übergebenen Kontext, um die gemeldete Datenbankoperation zum aufrufenden Anforderungshandler zuordnen zu können. Lassen Sie uns einige Anforderungen an den überarbeiteten Dienst senden und das Ergebnis betrachten:

Suche nach Wartezeiten in SQL-Transaktionen mit Elastic APM

Beachten Sie, dass die Span-Namen in der Datenbank nicht die komplette SQL-Anweisung enthalten, sondern nur einen Teil davon. Auf diese Weise können Sie etwa die Spans für Operationen mit einem bestimmten Tabellennamen mühelos aggregieren. Klicken Sie auf den Span, um die vollständige SQL-Anweisung in den Span-Details anzuzeigen:

Span-Details einer SQL-Abfrage in Elastic APM

Tracing für benutzerdefinierte Spans

Im vorherigen Abschnitt haben wir Spans für Datenbankabfragen zu unseren Traces hinzugefügt. Falls Sie den sich mit dem Dienst auskennen, ist Ihnen vielleicht aufgefallen, dass diese beiden Abfragen zur gleichen Operation gehören (ein Zähler wird abgefragt und anschließend aktualisiert). Falls zwischen oder in der Nähe dieser Abfragen viele Daten verarbeitet werden, kann es außerdem sinnvoll sein, diese Verarbeitung zur Methode „updateRequestCount“ zuzuweisen. Dazu erstellen wir einen benutzerdefinierten Span für diese Funktion.

Sie können benutzerdefinierte Spans auf verschiedene Arten erstellen, zum Beispiel mit apm.StartSpan. Übergeben Sie dieser Funktion einen Kontext mit einer Transaktion sowie einen Namen und einen Typ für den Span. Wir erstellen einen Span mit dem Namen „updateRequestCount“:

func updateRequestCount(ctx context.Context, name string) (int, error) {             
    span, ctx := apm.StartSpan(ctx, “updateRequestCount”, “custom”)
    defer span.End()
    ...
}

Wie Sie im obigen Code sehen, gibt apm.StartSpan einen Span und einen neuen Kontext zurück. Dieser neue Kontext enthält den neuen Span und sollte anstelle des übergebenen Kontexts verwendet werden. Die Benutzeroberfläche sieht jetzt wie folgt aus:

Tracing für benutzerdefinierte Spans in Elastic APM

Tracing für ausgehende HTTP-Anforderungen

Das bisher behandelte Tracing bezog sich immer auf einzelne Prozesse. Obwohl mehrere Dienste beteiligt sind, führen wir unser Tracing nur in einem einzigen Prozess aus: eingehende Anforderungen und Datenbankabfragen aus der Clientperspektive.

Microservices haben in den letzten Jahren stark an Beliebtheit zugenommen. Vor dem Aufkommen von Microservices wurden oft dienstorientierte Architekturen (Service-Oriented Architecture, SOA) verwendet, um monolithische Anwendungen in modulare Komponenten zu unterteilen. Beide Ansätze erhöhen die Komplexität, was wiederum die Observability erschwert. Wir müssen Operationen nicht nur innerhalb eines Prozesses zueinander zuordnen, sondern auch zwischen Prozessen und möglicherweise (vermutlich) sogar zwischen unterschiedlichen Computern, Rechenzentren oder externen Diensten.

Das Tracing innerhalb und zwischen Prozessen im Elastic APM Go Agent funktioniert etwa auf dieselbe Weise. Um eine ausgehende HTTP-Anforderung nachzuverfolgen, müssen Sie beispielsweise den HTTP-Client instrumentieren und sicherstellen, dass der umschließende Anforderungskontext an die ausgehende Anforderung weitergegeben wird. Damit kann der instrumentierte Client einen Span erstellen und Header in due ausgehende HTTP-Anforderung injizieren. In der Praxis sieht dies wie folgt aus:

// apmhttp.WrapClient instrumentiert den angegebenen http.Client
client := apmhttp.WrapClient(http.DefaultClient)
// Wenn „ctx“ einen Verweis auf eine laufende Transaktion enthält, startet der folgende Aufruf einen neuen Span.
resp, err := client.Do(req.WithContext(ctx))
…
resp.Body.Close() // the span is ended when the response body is consumed or closed

Wenn diese ausgehende Anforderung von einer anderen Anwendung verarbeitet wird, die mit Elastic APM instrumentiert wurde, erhalten Sie einen „verteilten Trace“, also einen Trace (eine Sammlung miteinander verwandter Transaktionen und Spans), der mehrere Dienste umspannt. Der instrumentierte Client injiziert einen Header, der den Span für die ausgehende HTTP-Anforderung identifiziert, und der empfangende Dienst extrahiert diesen Header und verwendet ihn, um den Client-Span zur aufgezeichneten Transaktion zuzuordnen. All diese Vorgänge werden von den verschiedenen unter go.elastic.co/apm/module bereitgestellten Instrumentierungsmodulen für Web-Frameworks bereitgestellt.

Als Demonstration werden wir unseren Dienst erweitern und zusätzliche Informationen zur Antwort hinzufügen: die Anzahl der Babys, die 2018 in Südaustralien mit demselben Namen geboren wurden. Der „hello“-Dienst erhält diese Informationen über eine HTTP-basierte API von einem zweiten Dienst. Der Code für diesen zweiten Dienst wird hier zur Verkürzung ausgelassen, aber Sie können sich eine ähnliche Implementierung und Instrumentierung wie im „hello“-Dienst vorstellen.

func helloHandler(w http.ResponseWriter, req *http.Request) {                             
        ...                                                                               
        stats, err := getNameStats(req.Context(), name)                                   
        if err != nil {
                panic(err)
        }                                                                                 
        fmt.Fprintf(w, "Hello, %s! (#%d)\n", name, requestCount)                          
        fmt.Fprintf(w, "In %s, %d: ", stats.Region, stats.Year)                           
        switch n := stats.Male.N + stats.Female.N; n {                                    
        case 1:                                                                           
                fmt.Fprintf(w, "there was 1 baby born with the name %s!\n", name)         
        default:                                                                          
                fmt.Fprintf(w, "there were %d babies born with the name %s!\n", n, name)  
        }                                                                                 
}                                                                                         
type nameStatsResults struct {                                                                    
        Region string                                                                             
        Year   int                                                                                
        Male   nameStats                                                                          
        Female nameStats                                                                          
}                                                                                                 
type nameStats struct {                                                                           
        N    int                                                                                  
        Rank int                                                                                  
}                                                                                                 
func getNameStats(ctx context.Context, name string) (nameStatsResults, error) {                   
        span, ctx := apm.StartSpan(ctx, "getNameStats", "custom")                                 
        defer span.End()                                                                          
        req, _ := http.NewRequest("GET", "http://localhost:8001/stats/"+url.PathEscape(name),
 nil)
        // Wir instrumentieren den HTTP-Client und fügen den umschließenden Kontext zur Anforderung hinzu.
        // Dadurch wird ein Span für die ausgehende HTTP-Anforderung erstellt, inklusive
        // eines Headers für verteiltes Tracing, um den Trace im Zieldienst fortzusetzen.
        client := apmhttp.WrapClient(http.DefaultClient)                                          
        resp, err := client.Do(req.WithContext(ctx))                                              
        if err != nil {                                                                           
                return nameStatsResults{}, err                                                    
        }                                                                                         
        defer resp.Body.Close()                                                                   
        var res nameStatsResults                                                                  
        if err := json.NewDecoder(resp.Body).Decode(&res); err != nil {                           
                return nameStatsResults{}, err                                                    
        }                                                                                         
        return res, nil                                                                           
}

Nachdem wir beide Dienste instrumentiert haben, wird ein verteilter Trace für jede Anforderung an den „hello“-Dienst angezeigt:

Verteiltes Tracing mit Elastic APM

Weitere Informationen zum verteilten Tracing finden Sie in Adam Quans Blogeintrag Verteiltes Tracing, OpenTracing und Elastic APM.

Ausnahmen- Panik-Tracking

Wir haben also gesehen, dass die Instrumentierungsmodule für Web-Frameworks eine Middleware zum Erfassen von Transaktionen bereitstellen. Außerdem erfassen sie Fehler (panics) und melden sie an Elastic APM, um die Analyse fehlgeschlagener Anforderungen zu erleichtern. Wir testen diese Funktion, indem wir updateRequestCount so anpassen, dass eine panic ausgelöst wird, wenn nicht-ASCII-Zeichen erkannt werde:

func updateRequestCount(ctx context.Context, name string) (int, error) {
    span, ctx := apm.StartSpan(ctx, “updateRequestCount”, “custom”)
    defer span.End()
    if strings.IndexFunc(name, func(r rune) bool {return r >= unicode.MaxASCII}) >= 0 {
        panic(“non-ASCII name!”)
    }
    ...
}

Senden sie jetzt eine Anforderung mit einigen nicht-ASCII-Zeichen:

curl -f http://localhost:8000/hello/世界
curl: (22) The requested URL returned error: 500 Internal Server Error

Hmm! Wo liegt das Problem? Öffnen Sie die APM-Benutzeroberfläche und suchen Sie auf der Seite „Errors“ nach dem Dienst „hello“:

Suche nach Dienstfehlern in Elastic APM

Hier sehen wir, dass ein Fehler aufgetreten ist, inklusive der Fehlermeldung (panic) „non-ASCII name!“ und dem Namen der Funktion, in der der Fehler aufgetreten ist: updateRequestCount. Klicken Sie auf den Namen des Fehlers, um zu den Details der aktuellsten Instanz des Fehlers zu gelangen. Auf der Seite mit den Fehlerdetails sehen wir den vollständigen Stacktrace, einen Snapshot mit den Details der entsprechenden Transaktion zum Zeitpunkt des Fehlers und einem Link zur abgeschlossenen Transaktion.

Drilldown in Transaktionsfehler mit Elastic APM

Sie können diese panics nicht nur erfassen, sondern können Fehler mit der Funktion apm.CaptureError auch explizit an Elastic APM melden. Übergeben Sie dieser Funktion einen Kontext mit einer Transaktion und einem Fehlerwert. „CaptureError“ gibt ein „apm.Error“-Objekt zurück, das Sie bei Bedarf anpassen und anschließend mit der „Send“-Methode finalisieren können:

if err != nil {
    apm.CaptureError(req.Context(), err).Send()
    return err
}

Zuletzt können Sie noch Logging-Frameworks integrieren, um Fehlerlogs an Elastic APM zu senden. Diesen Punkt werden wir im nächsten Abschnitt ausführlich behandeln.

Logging-Integration

In den letzten Jahren wurde viel über die „drei Grundpfeiler der Observability“ gesprochen: Traces, Logs und Metriken. Bisher haben wir uns mit dem Tracing beschäftigt, aber der Elastic Stack stellt alle drei Grundpfeiler bereit, und mehr. Wir werden uns später noch mit Metriken befassen, aber zunächst sehen wir uns an, wie Sie Elastic APM mit Ihrem Anwendungs-Logging integrieren können.

Wenn Sie schon mit zentralisiertem Logging gearbeitet haben, dann sind Sie vermutlich bereits mit dem Elastic Stack (ehemals auch ELK: Elasticsearch, Logstash, Kibana) vertraut. Wenn Sie Ihre Logs und Traces in Elasticsearch aufbewahren, können Sie sie mühelos miteinander referenzieren.

Der Go Agent bietet Integrationsmodule für verschiedene beliebte Logging-Frameworks: Logrus (apmlogrus), Zap (apmzap) und Zerolog (apmzerolog). Wir fügen etwas Logging mit Logrus zu unserem Webdienst hinzu und integrieren das Logging mit unseren Tracingdaten.

import "github.com/sirupsen/logrus"
var log = &logrus.Logger{                                                    
        Out:   os.Stderr,                                                
        Hooks: make(logrus.LevelHooks),                                  
        Level: logrus.DebugLevel,                                        
        Formatter: &logrus.JSONFormatter{                                
                FieldMap: logrus.FieldMap{                               
                        logrus.FieldKeyTime:  "@timestamp",              
                        logrus.FieldKeyLevel: "log.level",               
                        logrus.FieldKeyMsg:   "message",                 
                        logrus.FieldKeyFunc:  "function.name", // non-ECS
                },                                                       
        },                                                               
}                                                                        
func init() {
        apm.DefaultTracer.SetLogger(log)
}

Wir haben einen logrus.logger definiert, der nach stderr schreibt und die Logs als JSON formatiert. Für die Integration mit dem Elastic Stack ordnen wir einige der standardmäßigen Logfelder zu ihren Gegenstücken im Elastic Common Schema (ECS) zu. Als Alternative könnten wir den Standard beibehalten und Filebeat-Prozessoren für die Übersetzung verwenden, aber diese Lösung ist einfacher. Außerdem weisen wir den APM-Agent an, den Logrus-Logger für Debugnachrichten auf der Agentenebene zu verwenden.

Anschließend werden wir unsere Anwendungslogs mit den APM-Tracedaten integrieren. Wir fügen etwas Logging zu unserem Route-Handler helloHandler hinzu und ergänzen die Log-Nachrichten mit den entsprechenden Trace-IDs. Anschließend senden wir unsere Fehlerlog-Einträge an Elastic APM, um sie auf der Seite „Errors“ anzeigen zu können.

func helloHandler(w http.ResponseWriter, req *http.Request) {                
        vars := mux.Vars(req)
        log := log.WithFields(apmlogrus.TraceContext(req.Context()))                                            
        log.WithField("vars", vars).Info("handling hello request")       
        name := vars["name"]                                             
        requestCount, err := updateRequestCount(req.Context(), name, log)
        if err != nil {                                                  
                log.WithError(err).Error(“failed to update request count”)
                http.Error(w, "failed to update request count", 500)     
                return                                                   
        }                                                                
        stats, err := getNameStats(req.Context(), name)                                   
        if err != nil {
                log.WithError(err).Error(“failed to update request count”)
                http.Error(w, "failed to get name stats", 500)                            
                return                                                                    
        }                                                                                 
        fmt.Fprintf(w, "Hello, %s! (#%d)\n", name, requestCount)                          
        fmt.Fprintf(w, "In %s, %d: ", stats.Region, stats.Year)                           
        switch n := stats.Male.N + stats.Female.N; n {                                    
        case 1:                                                                           
                fmt.Fprintf(w, "there was 1 baby born with the name %s!\n", name)         
        default:                                                                          
                fmt.Fprintf(w, "there were %d babies born with the name %s!\n", n, name)  
        }  
}                                                                        
func updateRequestCount(ctx context.Context, name string, log *logrus.Entry) (int, error) {                          
        span, ctx := apm.StartSpan(ctx, "updateRequestCount", "custom")                                              
        defer span.End()                                                                                             
        if strings.IndexFunc(name, func(r rune) bool { return r >= unicode.MaxASCII }) >= 0 {                        
                panic("non-ASCII name!")                                                                             
        }                                                                                                            
        tx, err := db.BeginTx(ctx, nil)                                                                              
        if err != nil {                                                                                              
                return -1, err                                                                                       
        }                                                                                                            
        row := tx.QueryRowContext(ctx, "SELECT count FROM stats WHERE name=?", name)                                 
        var count int                                                                                                
        switch err := row.Scan(&count); err {                                                                        
        case nil:                                                                                                    
                if count == 4 {                                                                                      
                        return -1, errors.Errorf("no more")                                                          
                }                                                                                                    
                count++                                                                                              
                if _, err := tx.ExecContext(ctx, "UPDATE stats SET count=? WHERE name=?", count, name); err != nil { 
                        return -1, err                                                                               
                }                                                                                                    
                log.WithField("name", name).Infof("updated count to %d", count)                                      
        case sql.ErrNoRows:                                                                                          
                count = 1                                                                                            
                if _, err := tx.ExecContext(ctx, "INSERT INTO stats (name, count) VALUES (?, 1)", name); err != nil {
                        return -1, err                                                                               
                }                                                                                                    
                log.WithField("name", name).Info("initialised count to 1")                                           
        default:                                                                                                     
                return -1, err                                                                                       
        }                                                                                                            
        return count, tx.Commit()                                                                                    
}

Wenn wir jetzt das Programm ausführen und die Ausgabe in eine Datei (/tmp/hello.log, falls Sie unter Linux oder macOS arbeiten) umleiten, können wir Filebeat installieren und ausführen, um die Logs an denselben Elastic Stack zu senden, der auch die APM-Daten empfängt. Nachdem wir Filebeat installiert haben, passen wir die Konfiguration in der Datei „filebeat.yml“ wie folgt an:

  • Konfigurieren Sie „enabled: true“ für die Logeingabe unter „filebeat.inputs“, und ändern Sie den Pfad zu „/tmp/hello.log“.
  • Falls Sie Elastic Cloud verwenden, definieren Sie „cloud.id“ und „cloud.auth“, andernfalls definieren Sie „output.elasticsearch.hosts“.
  • Fügen Sie einen „decode_json_fields“-Prozessor hinzu, sodass der Abschnitt „processors“ wie folgt aussieht:
processors:
- add_host_metadata: ~
- decode_json_fields:
    fields: ["message"]
    target: ""
    overwrite_keys: true

Wenn Sie jetzt Filebeat ausführen, werden Logs generiert. Wenn wir jetzt einige Anforderungen an den Dienst senden, können wir mit der Aktion „Show host logs“ von Traces zu Logs für einen bestimmten Zeitpunkt springen.

Müheloser Wechsel zwischen APM-Daten und Quell-Logs

Mit dieser Aktion gelangen wir zur Logs-Benutzeroberfläche, gefiltert nach dem Host. Wenn Sie die Anwendung in einem Docker-Container oder in Kubernetes ausführen, werden Aktionen zum Verknüpfen von Logs für den Docker-Container bzw. den Kubernetes-Pod angezeigt.

Die Logs-Benutzeroberfläche in Kibana

Wenn Sie die Details des Logeintrags erweitern, sehen Sie, dass die Trace-IDs in den Lognachrichten enthalten sind. In Zukunft wird noch eine weitere Aktion hinzugefügt, mit der Sie die Logs nach einem bestimmten Trace filtern können, um nur relevante Lognachrichten anzuzeigen.

Analyse von Logdetails in der Log-Benutzeroberfläche

Wir können jetzt zwischen Traces und Logs hin- und herwechseln und werden uns jetzt den anderen Integrationspunkt ansehen: den Versand von Fehlerlogs an Elastic APM, um sie auf der Seite „Errors“ anzuzeigen. Dazu fügen wir einen apmlogrus.Hook zum Logger hinzu:

func init() {
        // apmlogrus.Hook sendet Lognachrichten mit den Stufen "error", "panic" und "fatal" an Elastic APM.
        log.AddHook(&apmlogrus.Hook{})
}

Zuvor haben wir updateRequestCount so geändert, dass nach dem vierten Aufruf ein Fehler zurückgegeben und von helloHandler in das Log geschrieben wird. Daher senden wir jetzt fünf Anforderungen für denselben Namen und sehen uns an, was auf der Seite „Errors“ angezeigt wird.

Fehlersuche mit Elastic APM

Wir sehen zwei Fehler. Einer der Fehler ist unerwartet und hängt mit der Verwendung einer speicherinternen Datenbank zusammen. Weitere Informationen finden Sie unter https://github.com/mattn/go-sqlite3/issues/204. Guter Fang! Wir sind jedoch wegen des Fehlers „failed to update request count“ hier.

Beachten Sie, dass beide Fehler aus updateRequestCount stammen. Woher hat Elastic APM diese Information? Wir verwenden das Modul github.com/pkg/errors, das jeden generierten oder umschlossenen Fehler mit einem Stacktrace ergänzt, und der Go Agent kann diese Stacktraces lesen.

Infrastruktur- und Anwendungsmetriken

Zum Abschluss kommen wir zu den Metriken. Ähnlich wie Sie mit Filebeat zwischen Host- und Containerlogs hin- und herspringen können, bietet Metricbeat die Möglichkeit zum Wechsel zwischen Host- und Containerinfrastrukturmetriken. Außerdem melden die Elastic APM Agents regelmäßig die CPU- und Arbeitsspeicherauslastung von System und Prozessen.

Überwachen von Infrastrukturmetriken mit Elastic APM

Die Agents können außerdem sprach- und anwendungsspezifische Metriken senden. Der Java Agent sendet beispielsweise JVM-spezifische Metriken, während der Go Agent Metriken für die Go-Laufzeit sendet, z. B. die aktuelle Anzahl an goroutines, die kumulative Anzahl der Heap-Zuweisungen und den Prozentanteil der für die Garbage Collection aufgewendeten Zeit.

Wir arbeiten daran, die Benutzeroberfläche für die Unterstützung zusätzlicher Metriken zu erweitern. Bis dahin können Sie eigene Dashboards erstellen, um die Go-spezifischen Metriken zu visualisieren.

Kibana-Dashboard mit Go-Metriken

Und das ist noch nicht alles!

Wir haben uns noch nicht angesehen, wie Sie den Real User Monitoring (RUM) Agent integrieren können, mit dem Sie einen verteilten Trace erhalten, der vom Browser über den gesamten Weg bis hin zu Ihren Backenddiensten reicht. Dieses Thema werden wir in einem zukünftigen Blogeintrag behandeln. In der Zwischenzeit können Sie sich einen Schluck Elastic-RUM gönnen.

In diesem Artikel haben wir vieles erreicht. Falls Sie weitere Fragen haben, können Sie diese jederzeit in unserem Diskussionsforum stellen, und wir werden uns nach Kräften bemühen, sie zu beantworten.