Spring for GraphQLのObservabilityってどうなっているか丁寧に追ってみる

# はじめに
今回は、Spring Bootで実装したGraphQLサーバの可観測性を調査していきたいと思います。
公式ドキュメントに乗っているトレースに着目して丁寧に説明していきます。

https://spring.pleiades.io/spring-graphql/reference/observability.html

# 想定読者
本記事は以下の項目に当てはまっている人を想定読者としています。
- Spring for GraphQLで何かしら実装したことがある人
- 可観測性をちょっとかじったことがある人

# サンプルコード（参考）
本記事では実装よりもどういったトレース情報が取れるのかに焦点を当てていますが、サンプルコードを実際に動かしてみて確認するとよいと思います。今回もSpring for GraphQLが公式で出しているコードを変更・拡張する形で実装しました。

https://spring.pleiades.io/guides/gs/graphql-server

# サンプルコードのGitHubリポジトリ
実装したコードはGitHub上から閲覧できます。実行方法および実行環境はgithubリポジトリのREADMEを参照してください

https://github.com/masakinakata/spring-graphql-observability

公式のサンプルコードとの変更点は以下に示すとおりです。
- トレース情報をとれるように依存関係の追加
- 例外ハンドラの追加

実際に構築したものは次のようになっています。各OSSが何をしているのかよくわからない場合は、後述の説明を読んでから、この図を見てください。

![image.png](https://qiita-image-store.s3.ap-northeast-1.amazonaws.com/0/3584503/3f1bed1c-2e0f-32b1-4e13-e543222ed267.png)


# 可観測性とは
可観測性（Observability、オブザーバビリティ、o11y）とは、システムの出力を調べることによって、システムの内部の状態を理解する能力のことを言います。そのためにはトレース、メトリクスやログといったものを出力して観測することになります。

https://opentelemetry.io/ja/docs/what-is-opentelemetry/#%e3%82%aa%e3%83%96%e3%82%b6%e3%83%bc%e3%83%90%e3%83%93%e3%83%aa%e3%83%86%e3%82%a3%e3%81%a8%e3%81%af%e3%81%aa%e3%81%ab%e3%81%8b

システムに可観測性を持たせるためのフレームワークとしてOpenTelemetryがあります。OpenTelemetryはフレームワークを提供しているだけでなく、トレース、メトリクスやログといった情報の仕様を決めているため、今回はOpenTelemetryの仕様に則ったトレースを見ていきます。

## トレースとは
トレースとは、アプリケーションにリクエストが投げられたときにどういう処理が行われるかの全体像が分かる情報になります。具体的には、HTTPリクエストのパスや実行される中身および結果などが経路として分かります。各経路にどのくらいの時間がかかったかといった情報は**スパン**として定義され可視化されます。

![image.png](https://qiita-image-store.s3.ap-northeast-1.amazonaws.com/0/3584503/55484baf-3372-02a2-da28-3e920aaba3f1.png)

https://opentelemetry.io/ja/docs/concepts/signals/traces/

# Spring for GraphQLに可観測性を持たせるには
## 依存関係の追加
Spring for GraphQLに可観測性が対応されていますが、依存関係を追加しないと自動的にトレース情報を出力してくれません。今回はSpring Bootのトレースの公式ドキュメントに則って可観測性を持たせます。

https://spring.pleiades.io/spring-boot/reference/actuator/tracing.html

gradleファイルに次の3つの依存関係を追加します。
```gradle:build.gradle

dependencies {
	...

	// 可観測性の追加
	implementation 'org.springframework.boot:spring-boot-starter-actuator'
	implementation 'io.micrometer:micrometer-tracing-bridge-otel'
	implementation 'io.opentelemetry:opentelemetry-exporter-zipkin'
}
```

`spring-boot-starter-actuator`では可観測性が自動計装されているため、設定をせずにトレースやメトリクスの情報をとってくれます。
`opentelemetry-exporter-zipkin`ではトレース情報を収集するバックエンドのZipkinに出力します。

## application.propertiesの設定
可観測性に関する設定値として、サンプリングの割合とトレースバックエンドのエンドポイントがあります。
それぞれ以下のように設定します。

```properties:application.properties
# トレース情報をバックエンドに送る割合を1にする
management.tracing.sampling.probability=1
# トレースバックエンドのエンドポイントを設定する
management.zipkin.tracing.endpoint=http://zipkin:9411/api/v2/spans
```

:::note warn
サンプリングの割合のデフォルト値は10%であり、トレースバックエンドのエンドポイントのデフォルト値は`http://localhost:9411/api/v2/spans`です。
:::

# Spring for GraphQLでのトレース情報を見てみる
次のような簡単なリクエストを送ったときのトレース情報を見てみます。
application.propertiesにて`spring.graphql.graphiql.enabled=true`にして、`localhost:8080/graphqiql`で確認します。

![image.png](https://qiita-image-store.s3.ap-northeast-1.amazonaws.com/0/3584503/785a1e09-c8c5-604e-6acb-652d2644ecf2.png)

Zipkinにアクセスしてみると経路が見られます
![image.png](https://qiita-image-store.s3.ap-northeast-1.amazonaws.com/0/3584503/55484baf-3372-02a2-da28-3e920aaba3f1.png)

### 最上位のスパン
GraphQLのリクエストについてかかった時間や何のリクエストか（GETやPOST）などHTTPプロトコルにかかわる情報が得られます。

### 2段目のスパン
リクエストの「GraphQLのクエリが何だったか」を表しています。

| タグ名 | 説明 | 例 |
| --- | --- | --- |
| `graphql.execution.id` | GraphQLのリクエストID。Spring for GraphQL内部では`graphql.execution.ExecutionId`として保持。| `c8cce1bd-c7c0-dc08-0801-425dcb3a03b0`|
| `graphql.operation` |GraphQLのオペレーション名。リクエストのクエリ名やミューテーション名が入る。 | `bookDetails` |
| `graphql.outcome` | GraphQLリクエストの結果。`SUCCESS`や`REQUEST_ERROR`等が入る。| `SUCCESS` |

### 3段目以降のスパン
GraphQLのクエリの各フィールドに対する情報を表します。

| タグ名 | 説明 | 例 |
| --- | --- | --- |
| `graphql.error.type` | エラーの結果。| `NONE` |
| `graphql.field.name` | フィールドの名前。| `bookById`や`author` |
| `graphql.outcome` | GraphQLリクエストの結果。 | `SUCCESS` |

## エラー時のトレース情報

### リクエスト時のクエリ不正
この章ではリクエスト時のクエリの内容が不正であった時のトレース情報を説明します。

次のように、`name`から`nam`へと存在しない引数を指定したリクエストのレスポンスは`Validation error`となります。

![image.png](https://qiita-image-store.s3.ap-northeast-1.amazonaws.com/0/3584503/eee757e1-29fe-53b2-204c-0bebed4b6a68.png)

このとき、トレース情報はController層に到達せず、GraphQLのリゾルバのところで処理が終了していることが分かります。さらに、タグの情報だけでなく結果の情報も紐づけられて出力されていることが確認できます。

![image.png](https://qiita-image-store.s3.ap-northeast-1.amazonaws.com/0/3584503/acecd1dc-18fd-0324-598f-5977807f396a.png)

### 業務ロジック内の例外発生
この章では業務ロジック内で例外が発生時のトレース情報を説明します。
本章で提示する例では、クエリの引数が`error`のときに`RuntimeException`を投げるようにController層のメソッドを修正しています。

#### デフォルトの挙動
リクエストのクエリの引数を`error`としたときに、Controller層のメソッド（`bookById`)でエラーが起きたことを確認できます。このときの`graphql.outcome`の値は`ERROR`となっていて、トレース上でもエラーとなっていることが分かります。

![image.png](https://qiita-image-store.s3.ap-northeast-1.amazonaws.com/0/3584503/305a6358-2227-06bb-dc1f-ebbe644eccd7.png)

#### 例外ハンドラの実装
`@GraphQlExceptionHandler`で実装したカスタムの例外ハンドラを指定したときの挙動についてみていきます。次のような簡単な例外ハンドラを実装します。
```java
@ControllerAdvice
public class BookControllerAdvice {
    @GraphQlExceptionHandler
    public GraphQLError exceptionHandle(Exception e) {
        return GraphQLError.newError()
                    .errorType(ErrorType.BAD_REQUEST)
                    .message(e.getMessage())
                    .build();
    }
}
```

この場合のトレース情報を見ると、`graphql.outcome`の値が`SUCCESS`となっています。
![image.png](https://qiita-image-store.s3.ap-northeast-1.amazonaws.com/0/3584503/582c9d18-147a-12ce-28c3-2de4d855ec62.png)

:::note info
`bookinfo:graphql filed book-by-id`と出ているスパンはControllerメソッドに対してのものではなく、**GraphQLのDataFetcherでの`bookById`クエリに対するスパン**になります。したがって、例外ハンドラにて例外から例外オブジェクトに変更された時点で結果は`SUCCESS`となっているのです。なので、業務ロジック内で例外が発生した場合は、各コントローラメソッドにてカスタムスパンを作成することが望ましいでしょう。
:::

例外ハンドラの実装やGraphQLのリクエスト処理の流れを知りたい場合は、私の過去記事もあわせて確認してください。

https://qiita.com/m4-nakata/items/7a57b3b95fc48fd7d050

# まとめ・感想
今回は、Spring for GraphQLの公式ドキュメントにある可観測性・トレースについて説明しました。
特に大した設定をしなくてもGraphQLの重要な部分のトレースはできているんじゃないかと思います。
例外ハンドラを呼ぶとエラーにしたい表示をエラーにできないので、カスタムスパンを作成する必要は出てきますね。この辺りはちょっと残念です（笑）Mappingアノテーションをカスタマイズしてスパンを作成するのがいいのかな？とか実装していて思いました。この辺りもアプリの要件次第ですね。