【2019年11月版】Apollo Server の GraphQL  API に OpenTracing を入れてみよう

# Apollo Server に OpenTracing を導入してみたいけど・・・？

今回は [OpenTracing](https://opentracing.io/) の一例として、Apollo Server の GraphQL API のトレースログを出してみたいと思います。

Apollo にはありがたいことに OpenTracing 対応のモジュール "[Apollo Opentracing](https://github.com/DanielMSchmidt/apollo-opentracing)" というモジュールがあるので、OpenTracing 仕様のログを出力するのは非常に簡単です。
先日の記事([【2019年10月版】TypeGraphQL なら ORM は TypeORM でしょう。](https://qiita.com/koinori/items/ef68b401a8f43d3556d6))で作成いたしました Apollo Server とテスト用の docker-compose を改造して、Jeager, Zipkin でトレースログを出力してみたいと思います!

## Jaeger でのトレースログ出力

それではまず、Jaeger へのログ出力を行ってみましょう。
以下の記事が非常に参考になるので(ほぼそのまま)、こちらの記事を参考に、Jaegerへの出力を行ってみたいと思います。

- [Apollo Server Integrated Performance Monitoring](https://developpaper.com/apollo-server-integrated-performance-monitoring/)

### 1. モジュールの追加

以下のコマンドにてモジュールを追加します。

```shell
$ npm i apollo-opentracing jaeger-client @types/jaeger-client
```

`apollo-opentracing` と、今回は Jaegerを使うので、 `jaeger-client` を使用します。また、`jaeger-client` の型定義、`@types/jaeger-client` を追加しました。

### 2. Tracer の作成

先ほどの記事を丸パクリして tracer を作成します。

```ts:tracer.ts
import { initTracer } from 'jaeger-client';

const config = {
  serviceName: 'apollo-typeorm-opentracing',
  sampler: {
    type: 'const',
    param: 1,
  },
  reporter: {
    logSpans: true,
    collectorEndpoint: 'http://localhost:14268/api/traces',
  },
}

const options = {
  logger: {
    info(msg: string) {
      console.log('INFO ', msg)
    },
    error(msg: string) {
      console.log('ERROR', msg)
    },
  },
}

export const tracer = initTracer(config, options)
```
今回は Jaeger は docker-composeでサクッと起動しますので、接続先は `localhost:14268` とします。

### 3. プラグインの投入

続いて Apollo Server の**プラグイン**として上記で作った `tracer` を登録します。`apollo-opentracing` 本家リポジトリの README にあるようにとりあえずシンプルなOpentracing 用 Extension を作成し、ApolloServer のコンストラクタで組み込みます。

```ts:server.ts
...
import { default as OpentracingExtension } from "apollo-opentracing";
...

  const server = new ApolloServer({
    schema, playground: true, introspection: true,
    extensions: [
      () => new OpentracingExtension({
        server: tracer,
        local: tracer
      })
    ]
  });
...
```
コードの対応は…なんとこれだけです！

### 4. Jaeger コンテナの追加

テスト用のコンテナ群に、Jaeger のコンテナを追加します。

今回は Jaeger のイメージは以下の AllInOneイメージを使用してしまいます。

- [https://www.jaegertracing.io/docs/1.14/getting-started/#all-in-one](https://www.jaegertracing.io/docs/1.14/getting-started/#all-in-one)

```yml:test/docker-compose.yml
...(前回の続き)
  jaeger:
    image: jaegertracing/all-in-one
    environment:
      - COLLECTOR_ZIPKIN_HTTP_PORT=9411
    ports:
      - 5775:5775/udp
      - 6831:6831/udp
      - 6832:6832/udp
      - 5778:5778
      - 16686:16686
      - 14268:14268
      - 9411:9411
```

はい、以上です！

### 5. 動作確認

まず、例によって docker-compose でテスト用の関連サーバー群を立ち上げます。

```
$ cd test

$ docker-compose up
```
ログを垂れ流して、MySQL がちゃんと3306ポートを待ち受け開始したか確認してくださいね！

MySQL ポートが開かれたら、新しいターミナルから、以下のコマンドでApollo Serverを起動します。

```
$ npm start
```

ブラウザから `Http://localhost:4000` を開き、立ちあがった PlayGrooundからGRaphQLのクエリをいくつか発行してみましょう。

そして、ブラウザから `http://localhost:16686` にアクセスしてください。

`Services` に上記の Tracer作成で指定した、`apollo-typeorm-opentracing` を選択し、"Find Traces" をクリックしてください。

以下のようにいくつかのアクセストレースログが表示されるかと思います。

![Jaeger UI.png](https://qiita-image-store.s3.ap-northeast-1.amazonaws.com/0/335150/9ed40af5-3f76-7c52-b2ab-fce52335fed8.png)

なかなかグラフィカルでいいですね！そして何より簡単！

ただし **TypeORMの対応がまだ** なので MySQL へ投げるクエリのOpentracing対応のログなどは自力でガリガリ実装する必要があるようです。。。

## Zipkin 対応

TypeORM は OpenTracing 対応していませんが、Zipkin には SQL のログなどが出せるようなので Zipkin でもトレースログの出力を試してみます。

対象のソースコードは上記の Jaeger の続き…ではなく、前回の記事の続きからとなります。

### 1. モジュールのインストール

今回は以下のモジュールを追加いたしました。

- apollo-opentracing
- opentracing
- zipkin-javascript-opentracing
- zipkin
- zipkin-transport-http

以下のコマンドでごっそりと投入いたします。

```shell
$ npm i apollo-opentracing opentracing zipkin-javascript-opentracing zipkin zipkin-transport-http
```

### 2. Tracer の作成

続いて Zipkin 用の `tracer` を作成いたします。

非常に簡易な Tracer ですが、以下の `zipkin-javascript-opentracing` 本家リポジトリのサンプルをそのまま拝借いたします。

- [https://github.com/DanielMSchmidt/zipkin-javascript-opentracing/tree/master/examples/vanillajs](https://github.com/DanielMSchmidt/zipkin-javascript-opentracing/tree/master/examples/vanillajs)

```ts:src/tracer.ts
import { BatchRecorder } from "zipkin";
import { HttpLogger } from "zipkin-transport-http";
const ZipkinJavascriptOpentracing = require("zipkin-javascript-opentracing");

const recorder = new BatchRecorder({
  logger: new HttpLogger({
    endpoint: "http://localhost:9411/api/v1/spans"
  })
});

// Setup the tracer to use http and implicit trace context
export const tracer = new ZipkinJavascriptOpentracing({
  serviceName: "TypeGraphQL TypeORM Sample",
  recorder,
  kind: "client"
});
```

`zipkin-javascript-opentracing` は TypeScript の対応が出来ていないようなので `require` してしまいます。

エンドポイントは後ほど `docker-compose.yml` で作成いたしますが、`localhost:9411` といたします。

### 3. TypeORM への仕込み

Zipking の TypeORM 用トレースログ流し込みプラグインとして `zipkin-instrumentation-typeorm` がありますが、今回はこれを使用したいと・・・思ったのですがバージョンが古くて現在の Zipkin には対応できていませんでした。
ちょっとした修正を行いましたので本家ではなく私のリポジトリを参照します。

以下のように dependencies に git のパスを直指定しておきます。

```json:package.json
...
  "dependencies": {
  ...
    "zipkin": "^0.19.1",
    "zipkin-instrumentation-typeorm": "git:https://github.com/Yoshinori-Koide-PRO/zipkin-instrumentation-typeorm.git",
    "zipkin-javascript-opentracing": "^2.0.1", 
  ...
  }
...
```
で、 `npm i` を実行してください。

続いて以下のように TypeORM のコネクションをハイジャックいたします。

```ts:Database.ts
import { createConnection } from "typeorm";
import { TypeOrmInstrumentation } from "zipkin-instrumentation-typeorm";

import { tracer } from "./tracer"

export const connection = createConnection("local").then(con => TypeOrmInstrumentation.proxyConnection(con, { tracer: tracer._zipkinTracer, serviceName: "TypeGraphQL TypeORM Sample" }))
```
`tracer` は import したままだと Opentracing 用の Tracer なので内部オブジェクトの`_zipkinTracer`を使用します。

これで Zipkin に SQL のログが流れます。

## 4. Opentracing 用 Extension の作成

続いて、Jeagerの場合と同様に Extension を作成し、ApolloServer に組み込みます。

```ts:src/server.ts
import { tracer } from "./tracer";
import { default as OpentracingExtension } from "apollo-opentracing";

...

  const server = new ApolloServer({
    schema, playground: true, introspection: true,
    extensions: [
      () => new OpentracingExtension({
        server: tracer,
        local: tracer
      })
    ]
  });
...
```

`OpentracingExtension` でいろいろやってくれるようですね～。

## 5. Zipkin サーバーの準備

テスト環境用の `docker-compose.yml` に zipkin を追加します。以下の `docker-compose-slim.yml`を使ってみました。

- [https://github.com/openzipkin-attic/docker-zipkin/blob/master/docker-compose-slim.yml](https://github.com/openzipkin-attic/docker-zipkin/blob/master/docker-compose-slim.yml)


```yml:docker-compose.yml
...(前回の続き)
  zipkin:
    image: openzipkin/zipkin-slim
    container_name: zipkin
    # Environment settings are defined here https://github.com/openzipkin/zipkin/blob/master/zipkin-server/README.md#environment-variables
    environment:
      - STORAGE_TYPE=mem
      # Uncomment to enable self-tracing
      # - SELF_TRACING_ENABLED=true
      # Uncomment to enable debug logging
      - JAVA_OPTS=-Dorg.slf4j.simpleLogger.log.zipkin2=debug
    ports:
      # Port used for the Zipkin UI and HTTP Api
      - 9411:9411
    depends_on:
      - storage

  # Fake services allow us to compose with docker-compose-elasticsearch.yml
  # BusyBox is pinned to prevent repetitive image pulls for no-op services
  storage:
    image: busybox:1.31.0
    container_name: fake_storage

  dependencies:
    image: busybox:1.31.0
    container_name: fake_dependencies
```

## 6.実行と動作確認

例によって以下のコマンドで docker-compose を立ち上げます。

```
$ cd test

$ docker-compose up
```
ログを垂れ流して、MySQL がちゃんと3306ポートを待ち受け開始したか確認してくださいね！

MySQL ポートが開かれたら、新しいターミナルから、以下のコマンドでApollo Serverを起動します。

```
$ npm start
```

ブラウザから `Http://localhost:4000` を開き、立ちあがった PlayGrooundからGRaphQLのクエリをいくつか発行してみましょう。

そして、ブラウザから `http://localhost:9441` にアクセスしてください。検索ボタンをクリックしてデータのロードをすると、以下のようにアクセスログが表示されいると思います。

![Zipkin.png](https://qiita-image-store.s3.ap-northeast-1.amazonaws.com/0/335150/b2ffe0e0-2776-fc31-9640-a4d47c9ca08c.png)

一つをクリックしてみると、内容が展開されて詳細が見れます。

![Zipkin アクセスログ.png](https://qiita-image-store.s3.ap-northeast-1.amazonaws.com/0/335150/657b2952-3181-9a8e-04b7-fa30765b9c86.png)

こちらはAPIのインタフェース = Resolve のメソッドが呼び出されたログですね。

また、SQLの場合は以下のような感じで表示されます。
![Zipkin SQLログ.png](https://qiita-image-store.s3.ap-northeast-1.amazonaws.com/0/335150/fc80a44a-3c18-db2a-d2b8-509a9ac309e4.png)

Zipkin はドリルダウンでどこにどれだけ時間がかかっているかがわかるのが魅力ですが、Apollo 用の Tracer と TypeORM用の Tracer がうまく連携できていないので別々のトレーサーとしてログが表示されています。う～ん、ちゃんと連携させるにはもう一工夫必要なようです。。。

とはいえAPIのアクセスログとSQLのトレースログが簡単に取れるので、これまでよりはボトルネックの割り出しが簡単にできそうです。
開発作業が収束してから重めの性能問題が発覚するのはキツイので、実装フェーズから積極的に Jaeger or Zipkin でのAPI性能チェックを開発作業に組み込めるようにしていきたいとおもいました。

## Githubに上げました。

上記のサンプルですが、github に上げました！

- Jaeger 版: [https://github.com/Yoshinori-Koide-PRO/apollo-typeorm-functions/tree/jaeger](https://github.com/Yoshinori-Koide-PRO/apollo-typeorm-functions/tree/jaeger)
- Zipkin 版: [https://github.com/Yoshinori-Koide-PRO/apollo-typeorm-functions](https://github.com/Yoshinori-Koide-PRO/apollo-typeorm-functions)

ご参考にどうぞ～。