バッチアプリにおけるOpentelemetryでの分散トレーシング検証メモ

# はじめに
Opentlemetryの分散トレーシングについていろいろ調査したが基本的にWebアプリのトレーシングに関する内容がほとんどで、APIをコールするBatchアプリについてトレーシングしたい場合の方法がわからなかったので、BatchアプリにおけるOpentelemetryの検証を行った。
今回はその検証内容についてメモとしてまとめる。

実現したい分散トレーシングのイメージは下図のとおりで、Batchアプリの起動から終了までの間を1Traceとしてトレーシングするのが目標。

![分散トレーシング.png](https://qiita-image-store.s3.ap-northeast-1.amazonaws.com/0/177076/1c888261-bec8-f6e5-b9af-27fa0ed01893.png)

利用するバージョンは下記の通り。

* opentelemetry：1.0.1
* Zipkin：2.23.2
* Java：OpenJDK 11.0.2

# 検証1：Webアプリ側のトレーシング検証
WebアプリのWebApp01に対してAPI Callしたときに正しく動作するか確認を行った。
WebApp01およびWebApp02はSpringBootで実装しており、ログにはTraceIdとSpanIdを出力する設定を入れている。
Webアプリの起動時に[こちらの記事](https://qiita.com/mkyz08/items/34d1861134fcdb3f8f7e)に記載されている方式を参考にし、あらかじめダウンロードしたAgentのjarを起動オプション指定し実行する。

Webアプリの起動コマンドは下記の通りである。

```bash
$ java -javaagent:opentelemetry-javaagent-all.jar -Dotel.traces.exporter=zipkin \ 
       -Dotel.zipkin.endpoint=http://localhost:9411/api/v2/spans \
       -Dotel.exporter.zipkin.service.name=web_app_01 \
       -Dotel.metrics.exporter=none \ # メトリックスはOFFにする
       -jar web-app-01/target/web-app-01.jar
```

Zipkinでの出力結果は下記のとおりであり、WebApp01 -> WebApp02についてのトレーシングできていることが確認できる。
※SerivceNameを指定しているにも関わらず、Zipkin上で`UNKNOWN_SERVICE`と表示される事象については現在調査中。

![image.png](https://qiita-image-store.s3.ap-northeast-1.amazonaws.com/0/177076/48f0f6c7-cef7-a40e-af15-48c222cd57f9.png)

# 検証2：Batchアプリのトレーシング検証(1)
Batchアプリに検証1と同じようにAgentを組み込んだ場合のトレーシング検証である。
Batchアプリのロギング設定にもWebアプリ同様にTraceId、SpanIdを設定している。
また、アプリの起動オプションははWebアプリと同じ設定としている。

Zipkinでの出力結果は下図の通りであり、バッチアプリ側はAPIのGetメソッド実行部分の処理からがトレーシング対象となっており、ジョブの起動から終了までの全体のトレーシングができていないことが確認できる。

![image.png](https://qiita-image-store.s3.ap-northeast-1.amazonaws.com/0/177076/cbfecce0-7e73-f638-385f-177ca42c70f1.png)

# 検証3：Batchアプリのトレーシング検証(2)
いろいろ検索した結果、`opentelemetry-extension-annotations`を利用することで任意のメソッドをトレーシング対象として設定することが判明したので、その方法でトレーシング検証を行う。

まずは、Batchアプリの依存ライブラリに`opentelemetry-extension-annotations`を追加する。

```xml:pom.xml
  <dependency>
    <groupId>io.opentelemetry</groupId>
    <artifactId>opentelemetry-extension-annotations</artifactId>
    <version>1.0.1</version>
  </dependency>
```

その後、BatchアプリでSpanとして計測したいメソッドに`@WithSpan`を設定する。

* 設定例

```java:SampleJobRunner.java
import io.opentelemetry.extension.annotations.WithSpan;
//省略

public class SampleJobRunner implements CommandLineRunner {

    @WithSpan
    public void run(String... args) throws Exception {
        final String jobName = System.getProperty("job.name");
        log.info("Job Start, JobName:{}.", jobName);
        apiCall();
        log.info("Job Finished, JobName:{}.", jobName);
    }

    @WithSpan
    private void apiCall() {
         //処理は省略
    }
}
```

上記設定後、「検証2：Batchアプリのトレーシング検証(1)」と同じ方法でBatchアプリを起動した結果、下図の通りBatchアプリのrunメソッドからトレーシングされていることが確認できた。

![image.png](https://qiita-image-store.s3.ap-northeast-1.amazonaws.com/0/177076/8a7af12d-77f4-678a-33f5-38c40d62bfe0.png)

また、Batchアプリのログ、Webアプリのログでは同じTraceIdでログ出力されていることも確認できた。

```log:batch
2021-06-19 21:28:24 trace:bc36ac3e733f5cc0f7875b08604fd005 span:e0748955ace7d29e thread:main level:INFO 	logger:com.example.sample.runner.SampleJobRunner       	message:Job Start, JobName:sample.
2021-06-19 21:28:24 trace:bc36ac3e733f5cc0f7875b08604fd005 span:f60deafc5f7d16a3 thread:main level:INFO 	logger:com.example.sample.runner.SampleJobRunner       	message:API Call, URL : http://localhost:8881/web01/sample.
2021-06-19 21:28:24 trace:bc36ac3e733f5cc0f7875b08604fd005 span:f60deafc5f7d16a3 thread:main level:INFO 	logger:com.example.sample.runner.SampleJobRunner       	message:StatusCode : 200 OK, Header : {Content-Type=application/json, Transfer-Encoding=chunked, Date=Sat, 19 Jun 2021 12:28:24 GMT, Keep-Alive=timeout=60, Connection=keep-alive}.
2021-06-19 21:28:24 trace:bc36ac3e733f5cc0f7875b08604fd005 span:f60deafc5f7d16a3 thread:main level:INFO 	logger:com.example.sample.runner.SampleJobRunner       	message:Response Message : web01-app-message.
2021-06-19 21:28:24 trace:bc36ac3e733f5cc0f7875b08604fd005 span:e0748955ace7d29e thread:main level:INFO 	logger:com.example.sample.runner.SampleJobRunner       	message:Job Finished, JobName:sample.
2021-06-19 21:28:24 trace:bc36ac3e733f5cc0f7875b08604fd005 span:fbb222846e9c58bd thread:main level:INFO 	logger:com.example.sample.JobRunner                    	message:Job Normally Finished, Execution time : 2152ms

```

```log:web-app-01/web-app-02
date:2021-06-19 21:28:24	trace:bc36ac3e733f5cc0f7875b08604fd005	span:e98db147d1913074	thread:http-nio-8881-exec-9	X-Track:	level:INFO 	logger:com.example.webapp01.Controller                 	message:getSample is Called.
date:2021-06-19 21:28:24	trace:bc36ac3e733f5cc0f7875b08604fd005	span:e98db147d1913074	thread:http-nio-8881-exec-9	X-Track:	level:INFO 	logger:com.example.webapp01.Controller                 	message:Header : {traceparent=00-bc36ac3e733f5cc0f7875b08604fd005-528fff0462f17bbb-01, host=localhost:8881, connection=keep-alive, accept=application/json, application/*+json, user-agent=Java/11.0.2}.
date:2021-06-19 21:28:24	trace:bc36ac3e733f5cc0f7875b08604fd005	span:e98db147d1913074	thread:http-nio-8881-exec-9	X-Track:	level:INFO 	logger:com.example.webapp01.Controller                 	message:API Call, URL : http://localhost:8882/web02/sample.
date:2021-06-19 21:28:24	trace:bc36ac3e733f5cc0f7875b08604fd005	span:7fad792962413c9e	thread:http-nio-8882-exec-8	X-Track:	level:INFO 	logger:com.example.webapp02.Controller                 	message:getSample is Called.
date:2021-06-19 21:28:24	trace:bc36ac3e733f5cc0f7875b08604fd005	span:7fad792962413c9e	thread:http-nio-8882-exec-8	X-Track:	level:INFO 	logger:com.example.webapp02.Controller                 	message:Header : {traceparent=00-bc36ac3e733f5cc0f7875b08604fd005-1930db76decfbcb2-01, host=localhost:8882, connection=keep-alive, accept=application/json, application/*+json, user-agent=Java/11.0.2}.
date:2021-06-19 21:28:24	trace:bc36ac3e733f5cc0f7875b08604fd005	span:e98db147d1913074	thread:http-nio-8881-exec-9	X-Track:	level:INFO 	logger:com.example.webapp01.Controller                 	message:StatusCode : 200 OK, Header : {Content-Type=application/json, Transfer-Encoding=chunked, Date=Sat, 19 Jun 2021 12:28:24 GMT, Keep-Alive=timeout=60, Connection=keep-alive}.
date:2021-06-19 21:28:24	trace:bc36ac3e733f5cc0f7875b08604fd005	span:e98db147d1913074	thread:http-nio-8881-exec-9	X-Track:	level:INFO 	logger:com.example.webapp01.Controller                 	message:Response Message : web02-app-message.
```

# 参考
* https://qiita.com/mkyz08/items/34d1861134fcdb3f8f7e
* https://github.com/open-telemetry/opentelemetry-java/tree/v1.0.1/examples/zipkin/src/main/java/io/opentelemetry/example/zipkin
* https://opentelemetry.io/docs/java/manual_instrumentation/#exporter
* https://opentelemetry.lightstep.com/java/