エンジニアリング

Elastic APMのGoエージェントでGoアプリをインストルメントする方法

Elastic APM(アプリケーションパフォーマンス監視)は、アプリケーションパフォーマンスに対する豊富なインサイトや分散ワークロードに対する可視性を提供します。また、GoJavaRubyPython、およびJavaScript(Node.jsおよびブラウザーでのリアルユーザー監視(RUM))を含む、多数の言語を公式にサポートしています。

パフォーマンスに関するインサイトを取得するためには、アプリケーションをインストルメントする必要があります。インストルメンテーションには、アプリケーションの動作を測定するためにアプリケーションのコードを変更することが必要です。サポートされている言語のいくつかについては、エージェントをインストールするだけで済みます。たとえば、Javaアプリケーションはシンプルな‑javaagentフラグを使用することで自動的にインストルメントでき、そこではバイトコードインストルメンテーションが使用されます。これはコンパイルされたJavaバイトコードを操作するプロセスであり、通常、プログラムのスタート時にJavaクラスがロードされる際に実行されるものです。これに加えて、単一スレッドでは最初から最後までのオペレーションを制御するのが一般的であるため、スレッドローカルストレージを使用してオペレーションを関連付けることができます。

一般的に、Goプログラムはネイティブマシンのコードにコンパイルされますが、これは自動インストルメンテーションにはあまり適していません。また、Goプログラムのスレッドモデルは他のほとんどの言語とは異なります。Goプログラムでは、コードを実行する「goroutine」がオペレーティングシステムのスレッド間を移動する場合があり、論理オペレーションは往々にして複数のgoroutineにまたがります。そのようなGoアプリケーションをどのようにしてインスルメントすればよいでしょうか。

この記事では、応答時間に関する詳細なパフォーマンスデータのキャプチャ(トレーシング)、インフラストラクチャーおよびアプリケーションのメトリックのキャプチャ、およびロギングとの統合(つまり監視性の3大要素)のために、Elastic APMでGoアプリケーションをインストルメントする方法を説明します。この記事では次のトピックについて順に触れながら、アプリケーションとそのインストルメンテーションを構築する方法を説明します。

Webリクエストのトレーシング

Elastic APMのGoエージェントは、サーバーへの着信リクエストなど、「トレーシング」オペレーション用のAPIを提供します。オペレーションのトレーシングには、オペレーション名、タイプ/カテゴリー、いくつかの属性(ソースIP、認証ユーザー、その他)など、イベント(オペレーションを説明するもの)の記録が含まれます。イベントは、オペレーションの開始時間や継続時間を記録し、オペレーションの繋がりを記述する識別子も記録します。

Elastic APMのGoエージェントは、さまざまなWebフレームワーク、RPCフレームワーク、データベースドライバーをインストルメントするため、およびいくつかのロギングフレームワークと統合するための多数のモジュールを提供します。サポートされているテクノロジーの完全なリストをご確認ください。

gorilla/muxルーターを使用して、シンプルなWebサービスにElastic APMによるインストルメンテーションを追加し、そのパフォーマンスをElastic APMでキャプチャする方法について説明していきましょう。

以下がインストルメントされていないオリジナルのコードです。

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))           
}

gorilla/muxルーターからのリクエストをインストルメントするには、ミドルウェアをサポートするgorilla/muxの最新バージョン(v1.6.1以降)が必要です。さらに必要なのは、go.elastic.co/apm/module/apmgorillaをインポートして、以下のコード行を追加することだけです。

r.Use(apmgorilla.Middleware())

このapmgorillaミドルウェアは、各リクエストをトランザクションとしてAPMサーバーにレポートします。ここでインストルメンテーションから離れて、それがAPM UIでどのように表示されるかについて見てみましょう。

パフォーマンスのビジュアル化

Webサービスのインストルメンテーションを設定しましたが、データを送信する場所がありません。APMエージェントは、デフォルトではAPMサーバー(http://localhost:8200)へのデータ送信を試みます。最近リリースされたElastic Stack 7.0.0を使用して、新しいスタックをセットアップしてみましょう。スタックのデフォルトのデプロイを無料でダウンロードすることができます。またはElastic Cloud上でElasticsearch Serviceの14日間無料トライアルの使用を開始することができます。ローカルで実行する場合は、Docker Composeの構成例を https://github.com/elastic/stack-dockerで見つけることができます。

スタックをセットアップしたら、データをAPMサーバーに送信するようにアプリケーションを構成できます。APMサーバーのURLとシークレットトークンを知っておく必要があります。Elastic Cloudを使用する場合、これらはデプロイ時に「Activity」ページで、およびデプロイ完了後に「APM」ページで見つけることができます。デプロイ時にはElasticsearcとKibanaのパスワードもメモしておく必要があります。これは後から再度見ることはできません(必要な場合はリセットできます)。

Elasticsearch ServiceのCloud Console内のElastic APM

APMのGoエージェントは環境変数によって構成されます。APMサーバーURLとシークレットトークンを構成するには、アプリケーションがそれらを取得できるように以下の環境変数をエクスポートします。

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

これで、インストルメントされるプログラムを実行し、少し待つとAPM UIにいくつかのデータが表示されます。このエージェントは定期的に次のメトリックを送信します:CPUおよびメモリの使用状況、Goランタイムの統計。エージェントはリクエストがあるとトランザクションの記録も行います。デフォルトではこれらはバッファされ、10秒ごとにバッチで送信されます。では、サービスを実行し、リクエストを送信して、どうなるかを見てみましょう。

イベントが正常にAPMサーバーに送信されていることを確認するために、追加の環境変数を設定することができます。

export ELASTIC_APM_LOG_FILE=stderr
export ELASTIC_APM_LOG_LEVEL=debug

ここでアプリケーションを起動します(hello.goには以前からインストルメントしているプログラムが含まれています)。

go run hello.go

次に、github.com/rakyll/heyを使用してサーバーにリクエストを送信します。

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

アプリケーションの出力は次のようになるはずです。

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

そして、heyの出力として、応答時間の遅延に関するヒストグラムなど、さまざまな統計が表示されるはずです。ここでKibanaを開いてAPM UIにナビゲーションすると、「hello」という名前のサービスと、「/hello/{name}」という名前の1つのトランザクショングループが表示されるはずです。見てみましょう。

Elastic APMで利用可能なサービスのリスト

Elastic APMで「hello」サービスの詳細を確認

いくつかの疑問点があるはずです。エージェントはどのようにしてサービスに与える名前を認識するのか、リクエストURIではなくルートパターンが使用されるのはなぜか、などです。最初の質問は簡単です。(環境変数を使用して)サービス名を指定しなければ、プログラムのバイナリ名が使用されます。この場合、プログラムは「hello」という名前のバイナリにコンパイルされます。

そして、ルートパターンが使用される理由は、集計を有効化するためです。ここでトランザクションをクリックすると、応答時間の遅延に関するヒストグラムが表示されます。

Elastic APMで表示されるトランザクション時間の遅延

ルートパターンで集計していても、完全なリクエストURLをトランザクションプロパティで確認できることにご注意ください。

SQLクエリのトレーシング

典型的なアプリケーションには、データベースやキャッシュなどの外部のサービスが関与したさらに複雑なロジックがあります。アプリケーションのパフォーマンス問題の診断を試みるためには、これらのサービスとのインタラクションを確認できることが重要です。

GoアプリケーションによるSQLクエリを監視する方法を見てみましょう。

デモンストレーション用として、組み込みのSQLiteデータベースを使用しますが、database/sqlを使用している限り、どのドライバーを使用しても構いません。

database/sqlオペレーションをトレースするために、Elasticではインストルメントモジュールのgo.elastic.co/apm/module/apmsqlを提供します。apmsqlモジュールは、データベースオペレーションをトランザクション内のspansとしてレポートするためにdatabase/sqlドライバーをインストルメントします。このモジュールを使用するためには、データベースドライバーを登録および開く方法を変更する必要があります。

アプリケーションでは通常、database/sqlドライバーを登録するために、database/sqlパッケージをインポートします。その例は次のとおりです。

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

同様のことができるように、Elasticはいくつかの便利なパッケージを提供します。ただしこれらは、同じドライバーのインストルメントされているバージョンを登録します。たとえば、SQLite3の場合、次のようにインポートします。

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

ここではカバーの下で、apmsql.Registerメソッドを使用します。これはsql.Registerをコールするのと同等ですが、登録されたドライバーをインストルメントします。apmsql.Registerを使用する時は常に、 sql.Openを使用するのではなくpmsql.Openを使用して接続を開く必要があります。

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)
        }
        ...
}

最初のほうで、Goは他の多くの言語とは異なり、関連オペレーションを一緒に試行するためのスレッドローカルのストレージ機能があることを説明しました。その代わり、コンテキストを明示的に伝える必要があります。Webリクエストのトランザクションの記録を開始すると、進行中のトランザクションのリファレンスがリクエストコンテキストに保存されます。これはnet/http.Request.Contextで実行されます。それがどのように表示されるかを見てみましょう。各名前が表示された回数を記録し、データベースクエリをElastic APMにレポートします。

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は、名前のカウントをdbでインクリメントし、新しいカウントを返します。
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()                                                                                           
}

このコードには指摘すべき重要なポイントが2つあります。

  • database/sql *Contextメソッドを使用していること(ExecContext、 QueryRowContext)
  • 囲んでいるリクエストからそれらのメソッドコールにコンテキストを渡していること

apmsqlでインストルメントされているデータベースドライバーは、提供されたコンテキスト内での進行中のトランザクションへのリファレンスを見つけることを想定しています。これは、レポートされたデータベースオペレーションが、それを呼び出しているリクエストハンドラーと関連付けられる方法です。 この改良されたサービスにいくつかのリクエストを送信して、どのようになるかを見てみましょう。

Elastic APMでSQLトランザクションの遅延を検索

データベースのスパン名は完全なSQLステートメントを保持せず、その一部のみを保持していることに注意してください。これにより、たとえば特定のテーブル名でのオペレーションを表すスパンをより簡単に集約できます。スパンをクリックすることで、スパンの詳細で完全なSQLステートメントを見ることができます。

Elastic APMでSQLクエリのスパン詳細を確認

カスタムスパンのトレーシング

前のセクションでは、トレースにデータベースクエリスパンを導入しました。サービスに精通している方なら、これら2つのクエリが同じオペレーションの各部分(クエリして、その後カウンターを更新)であることをすぐに理解できると思いますが、そうでない方は分からないかもしれません。さらに、これらのクエリの間や前後で重大な処理が進行している場合は、それを“updateRequestCount”メソッドに属性付けすると便利な場合があります。これは、その関数のカスタムスパンをレポートすることでできます。

カスタムスパンはさまざまな方法でレポートできますが、最も簡単な方法はapm.StartSpanを使用する方法です。この関数に、トランザクション、スパンの名前およびタイプを含むコンテキストを渡す必要があります。「updateRequestCount」という名前のスパンを作成しましょう。

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

上記のコードのとおり、apm.StartSpanはスパンと新しいコンテキストを返します。その新しいコンテキストは、コンテキストが渡される場所で使用されます。そこには新しいスパンが含まれています。UIでは次のように表示されます。

Elastic APMでのカスタムスパンのトレーシング

発信HTTPリクエストのトレーシング

ここまでの説明内容は、シングルプロセストレーシングについてでした。複数のサービスが関与している場合でも、1つのプロセス内でのみトレーシングしています。つまり、受信リクエスト、クライアントの視点からのデータベースクエリです。

最近では、マイクロサービスがますます一般的になってきています。マイクロサービスが登場する前は、サービス指向アーキテクチャ(SOA)が、モノリシックアプリケーションをモジュールコンポーネントに分解するもう1つの一般的なアプローチでした。どちらの場合でも複雑さが増し、結果として監視性が複雑化します。現在では、オペレーションを1つのプロセス内で関連付けるだけでなく、プロセス間、(高い確率で)異なるマシン間、さらに異なるデータセンター間やサードパーティサービス間でも関連付ける必要があります。

Elastic APMのGoエージェントのプロセス内およびプロセス間のトレースの処理方法はほぼ同じです。たとえば、発信HTTPリクエストをトレースするためにはHTTPクライアントをインストルメントする必要があり、含まれているリクエストコンテキストが発信リクエストに伝達されるようにする必要があります。インストルメントされるクライアントはそれを使用してスパンを作成し、発信HTTPリクエストへのヘッダーの入力も行います。実際の例を見てみましょう。

// apmhttp.WrapClientは特定のhttp.Clientをインストルメントします
client := apmhttp.WrapClient(http.DefaultClient)
// 進行中のトランザクションへのリファレンスが「ctx」に含まれている場合、下記のコールで新しいスパンが開始されます。
resp, err := client.Do(req.WithContext(ctx))
…
resp.Body.Close() // the span is ended when the response body is consumed or closed

この発信リクエストが、Elastic APMでインストルメントされている別のアプリケーションで処理された場合、「分散トレース」となります。つまり、サービス間に渡るトレース(関連するトランザクションおよびスパンの収集)です。インストルメントされているクライアントは、発信HTTPリクエストのスパンを特定するヘッダーを入力します。そして受信サービスはそのヘッダーを抽出し、それを使用してクライアントのスパンを、記録するトランザクションに関連付けます。これらのすべては、go.elastic.co/apm/moduleで提供されるさまざまなWebフレームワークインストルメンテーションモジュールで処理されます。

これをデモンストレーションするために、ここではサービスを拡張して、応答に豆知識「2018年に南オーストラリアで生まれた特定の名前の赤ちゃんの数」が追加されるようにします。「hello」サービスはこの情報を、2つ目のサービスからHTTPベースのAPIを経由して取得します。この2つ目のサービスのコードは簡潔にするために省略されていますが、「hello」サービスとほぼ同じ方法で実装およびインストルメントされていることが想像できます。

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)
        // HTTPクライアントをインストルメントし、周辺のコンテキストをリクエストに追加します。
        // これにより、発信HTTPリクエストのスパンが生成され、
        // そこにはターゲットサービスでのトレーシングを継続するための分散トレーシングヘッダーが含まれています。
        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                                                                           
}

両方のサービスをインストルメントすることで、「hello」サービスに対する各リクエストの分散トレーシングを確認できます。

Elastic APMでの分散トレーシング

分散トレーシングに関するトピックの詳細については、Adam Quanによるブログ記事「分散トレーシング、OpenTracingとElastic APM」をご覧ください。

例外のパニックトラッキング

ここまで見てきたように、Webフレームワークインストルメンテーションモジュールは、トランザクションを記録するミドルウェアを提供します。これに加えて、それらのモジュールはパニックもキャプチャし、失敗したリクエストの調査に役立つようにそれをElastic APMにレポートします。これを試してみましょう。updateRequestCountが非ASCII文字を見つけてパニックになるようにしてみます。

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!”)
    }
    ...
}

では、非ASCII文字を含むリクエストを送信します。

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

さて、この問題はどのようになるでしょうか。APM UIを見てみましょう。「hello」サービスのErrorページにアクセスします。

Elastic APMでのサービスエラー表示

ここではエラーが発生したことが示されており、エラー(パニック)メッセージ「non-ASCII name!」と、そのパニックの発生元である関数名「updateRequestCount」が表示されています。エラー名をクリックすると、そのエラーの直近のインスタンスの詳細にリンクされます。エラー詳細ページには、フルスタックのトレース、エラーが発生したトランザクションの詳細のスナップショット(エラー発生時)、および完了したトランザクションへのリンクが表示されます。

Elastic APMでトランザクションエラーをドリルダウン

このようなパニックをキャプチャすることに加えて、apm.CaptureError関数を使用することでエラーを明示的にElastic APMにレポートすることもできます。この関数に、トランザクションとエラー値を含むコンテキストを渡す必要があります。CaptureErrorが「apm.Error」オブジェクトを返します。これはオプションとしてカスタマイズすることができ、Sendメソッドを使用してファイナライズします。

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

最後に、エラーログをElastic APMに送信するために、ロギングフレームワークと統合することが可能です。このことについて、次のセクションでさらに説明します。

ロギングの統合

最近、「監視性の3つの柱」、つまりトレース、ログ、メトリックについてよく話すようになりました。ここまで見てきたのはトレーシングですが、Elastic Stackでは監視性の3つの柱のすべてと、それ以外のものにも対応します。メトリックについてはのちほど説明するとして、まずはElastic APMとアプリケーションロギングの統合方法を見ていきましょう。

どのような種類であっても一元化されたロギングを実行したことがあるなら、Elastic Stack(旧称ELK = Elasticsearch、Logstash、Kibana)についてはすでによくご存じでしょう。ログとトレースの両方をElasticsearchに集約しているなら、それらの相互参照は簡単です。

Goエージェントには、いくつかの有名なロギングフレームワーク向けの統合モジュールがあります。それらのフレームワークには、Logrus(apmlogrus)、Zap(apmzap)、およびZerolog(apmzerolog)が挙げられます。Logrusを使用してWebサービスにロギングを追加し、それをトレーシングデータと統合する方法を見てみましょう。

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)
}

stderrに書き込むlogrus.Loggerを構築しました。ログのフォーマットはJSONです。より適切にElastic Stackに合うように、標準のログフィールドをElastic Common Schema(ECS)の同等のフィールドにマッピングします。または、それらのフィールドをデフォルトのままにしておき、Filebeatプロセッサーを使用して変換することも可能ですが、マッピングするほうがよりシンプルです。また、エージェントレベルのデバッグメッセージのロギングにこのLogrusロガーを使用するようAPMエージェントに指示しました。

では、アプリケーションログとAPMトレースデータを統合する方法を見てみましょう。いくつかのロギングをhelloHandlerルートハンドラーに追加し、トレースIDをログメッセージに追加する方法を見てみます。その後、「Error」ページに表示されるようにエラーログの記録をElastic APMに送信する方法を説明します。

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()                                                                                    
}

ここで、出力がファイル(/tmp/hello.log。LinuxまたはmacOSで実行していると想定)にリダイレクトされる状態でプログラムを実行すると、Filebeatをインストールおよび実行することで、APMデータを受信する同じElastic Stackにログを送信できます。Filebeatをインストールした後、その構成はfilebeat.ymlで次のようにして変更できます。

  • 「filebeat.inputs」の下でログ入力を「enabled: true」に設定し、パスを「/tmp/hello.log」に変更します。
  • Elastic Cloudを使用している場合は、「cloud.id」および「cloud.auth」に設定します。Elastic Cloudを使用していない場合は「output.elasticsearch.hosts」に設定します。
  • 「decode_json_fields」プロセッサーを追加します。「processor」は次のようになります。
processors:
- add_host_metadata: ~
- decode_json_fields:
    fields: ["message"]
    target: ""
    overwrite_keys: true

Filebeatを実行すると、ログの送信が開始されます。ここでリクエストをサービスに送信すると、「Show host logs」アクションを使用することで、トレースから直接、その同時点のログにアクセスすることができます。

APMデータからソースログに直接アクセス

このアクションではLogs UIにジャンプし、ホストにフィルターされています。アプリケーションがDockerコンテナー内またはKubernetes内で実行されている場合は、DockerコンテナーまたはKubernetesポッドのログへとつなぐアクションが可能です。

Kibana内のLogs UI

ログ記録の詳細を展開すると、トレースIDがログメッセージに含まれていることが分かります。今後は、ログを特定のトレースにフィルターするための別の機能を追加する予定です。これにより、関連するログメッセージのみを表示できるようになります。

Log UI内でログの詳細を確認

トレースからログへと直接アクセスすることができるようになりました。次に他の統合ポイントを見てみましょう。エラーログをElastic APMに送信して「Error」ページに表示されるようにします。そのためには、apmlogrus.Hookをロガーに追加する必要があります。

func init() {
        // apmlogrus.Hookが「error」、「panic」、および「fatal」ログメッセージをElastic APMに送信します。
        log.AddHook(&apmlogrus.Hook{})
}

前の手順でupdateRequestCountを変更し、4度目のコールの後にエラーを返すようにしました。また、helloHandlerを変更して、それをエラーとしてログするようにしました。同じ名前で5回リクエストを送信して、「Error」ページにどのように表示されるかを見てみましょう。

Elastic APMでのエラーのトレーシング

ここでは2つのエラーが表示されています。1つは、インメモリデータベースの使用に起因する予想外のエラーです。その説明については、https://github.com/mattn/go-sqlite3/issues/204をご覧ください。見事に捕捉しています。そして「failed to update request count」エラーが表示されています。

これら両方のエラーの原因がupdateRequestCountとなっていることに気付くはずです。Elastic APMはどのようにしてそれを知ったのでしょうか?github.com/pkg/errorsを使用しているため、それによって生成またはラップされる各エラーにスタックトレースが追加されます。Goエージェントはそれらのスタックトレースを利用することができます。

インフラストラクチャーおよびアプリケーションのメトリック

最後はメトリックです。Filebeatを使用してホストおよびコンテナーログに直接アクセスする方法と同様、Metricbeatを使用してホストおよびコンテナーのインフラストラクチャーメトリックに直接アクセスすることができます。さらに、Elastic APMエージェントは定期的に、システムおよびプロセスによるCPUとメモリの使用状況をレポートします。

Elastic APMでのインフラメトリックの追跡

また、エージェントは言語およびアプリケーション固有のメトリックも送信できます。たとえば、JavaはJVM固有のメトリックを送信し、GoエージェントはGoランタイムのメトリックを送信します(例:現在のgoroutines数、ヒープ割り当ての累積数、ガベージコレクションに費やした時間の割合)。

現在、さらに多くのアプリケーションメトリックをサポートするようにUIの拡張に取り組んでいます。それまでの間、Go固有のメトリックを視覚化するダッシュボードを作成することができます。

Goメトリックが多数表示されたKibanaダッシュボード

まだあります!

ここでは説明しませんでしたが、リアルタイムユーザー監視(RUM)エージェントとの統合も可能です。これにより、ブラウザーからバックエンドサービスまでのすべての分散トレーシングを確認できます。このトピックについては今後のブログで取り上げる予定です。それまでの間、Elastic RUM(Real User Monitoring)の概要をお読みください。

この記事ではさまざまな内容をカバーしています。さらにご質問がある場合は、ディスカッションフォーラムにご参加いただければ、できる限りお答えいたします。