OpenTelemetry Collectorがそれ自身のオブザーバビリティをどのように提供しているか？
Hi, この記事は OpenTelemetry Advent Calendar 2022、12日目の記事です！
OpenTelemetryは、Collectorを通じてバックエンドにテレメトリーデータを送信するアーキテクチャを取ることができます。それにより、様々なコンポーネントのテレメトリを統合し、関連付け、バックエンドへの送信を管理することができるようになっています。
反面、「バックエンドでテレメトリーデータが上手く表示されない」のようなトラブル時に、調査対象コンポーネントがそれだけ増えてしまうことになります。どのようにトラブルシュートすべきか、エージェント等のGitHubリポジトリから docs/troubleshooting.md などのドキュメントを探していただくとヒントがあるわけですが、OpenTelemetry Collectorではどのようなトラブルシュートができるか、そのためにどのようなオブザーバビリティを備えているかを見てみましょう。
メトリクス
OpenTelemetry Collectorはそれ自身で、Prometheus形式（OpenMetrics形式って言って良いんだっけ？）のメトリクスを公開しています。デフォルトの状況では 8888 ポートの /metrics エンドポイントで公開していて、たとえばこんな情報が手に入ります。
# HELP otelcol_exporter_sent_log_records Number of log record successfully sent to destination.
# TYPE otelcol_exporter_sent_log_records counter
otelcol_exporter_sent_log_records{exporter="signalfx",service_instance_id="37d4a1a7-5f40-4e89-9f70-203d101a5afa",service_name="otelcol",service_version="v0.66.0"} 20
otelcol_exporter_sent_log_records{exporter="splunk_hec",service_instance_id="37d4a1a7-5f40-4e89-9f70-203d101a5afa",service_name="otelcol",service_version="v0.66.0"} 624
# HELP otelcol_exporter_sent_metric_points Number of metric points successfully sent to destination.
# TYPE otelcol_exporter_sent_metric_points counter
otelcol_exporter_sent_metric_points{exporter="signalfx",service_instance_id="37d4a1a7-5f40-4e89-9f70-203d101a5afa",service_name="otelcol",service_version="v0.66.0"} 10254
実際には前後にズラーッと並んでいて一つひとつ解説するのは大変なので割愛しますが、Collectorの内部、receiverやprocessor、exporterがどのように動いているかのメトリクスを収集して、様子がわかるようにしています。これにより、たとえばこんなダッシュボードが作れたりします。
たとえば「あれ？トレースがあるはずなのにUI上でみれないぞ？」という場合は、まず、こういったダッシュボードを使って、テレメトリーデータのパイプラインが動作しているかを確認してみてください。
ちなみに、SplunkディストリビューションのCollectorではデフォルトとして、内部メトリクスをスクレイプするためのレシーバーが定義されていたりします。これにより、10秒に1回、自分自身のメトリクスをスクレイプし、メトリクスパイプラインに乗せて外部に送信するようになっています。
# This section is used to collect the OpenTelemetry Collector metrics # Even if just a Splunk APM customer, these metrics are included prometheus/internal: config: scrape_configs: - job_name: 'otel-collector' scrape_interval: 10s static_configs: - targets: ['0.0.0.0:8888'] metric_relabel_configs: - source_labels: [ __name__ ] regex: '.*grpc_io.*' action: drop
ログ
メトリクスによって、特定のコンポーネントやパイプラインが動いているかいないかが大雑把に判断できます。では、何故動いていないのか？原因を探るためにログを確認することがあります。OSのサービスとしてインストールした場合にはjournalログに、コンテナとして動かした場合にはコンテナログを見に行くのが基本です。
たとえば、SplunkディストロのCollectorの場合は、↓のようなコマンドでCollectorのログを確認できます。
sudo journalctl -u splunk-otel-collector
ログはこんな感じ。各コンポーネントやパイプラインの初期化の様子が主にinfoログとして出力されます。
Dec 12 09:03:07 mlrt otelcol[164910]: 2022-12-12T09:03:07.730Z info pipelines/pipelines.go:102 Receiver is starting... {"kind": "receiver", "name": "otlp", "pipeline": "traces"}
Dec 12 09:03:07 mlrt otelcol[164910]: 2022-12-12T09:03:07.730Z info pipelines/pipelines.go:106 Receiver started. {"kind": "receiver", "name": "otlp", "pipeline": "traces"}
Dec 12 09:03:07 mlrt otelcol[164910]: 2022-12-12T09:03:07.730Z info pipelines/pipelines.go:102 Receiver is starting... {"kind": "receiver", "name": "smartagent/signalfx-forwarder", "pipeline": "traces"}
Dec 12 09:03:07 mlrt otelcol[164910]: 2022-12-12T09:03:07.730Z info pipelines/pipelines.go:106 Receiver started. {"kind": "receiver", "name": "smartagent/signalfx-forwarder", "pipeline": "traces"}
Dec 12 09:03:07 mlrt otelcol[164910]: 2022-12-12T09:03:07.730Z info pipelines/pipelines.go:102 Receiver is starting... {"kind": "receiver", "name": "zipkin", "pipeline": "traces"}
Dec 12 09:03:07 mlrt otelcol[164910]: 2022-12-12T09:03:07.730Z warn internal/warning.go:51 Using the 0.0.0.0 address exposes this server to every network interface, which may facilitate Denial of Service attacks {"kind": "receiver", "name": "zipkin", "pipeline": "traces", "documentation": "https://github.com/open-telemetry/opentelemetry-collec>
Dec 12 09:03:07 mlrt otelcol[164910]: 2022-12-12T09:03:07.730Z info pipelines/pipelines.go:106 Receiver started. {"kind": "receiver", "name": "zipkin", "pipeline": "traces"}
Dec 12 09:03:07 mlrt otelcol[164910]: 2022-12-12T09:03:07.731Z info pipelines/pipelines.go:102 Receiver is starting... {"kind": "receiver", "name": "fluentforward", "pipeline": "logs"}
Dec 12 09:03:07 mlrt otelcol[164910]: 2022-12-12T09:03:07.731Z info pipelines/pipelines.go:106 Receiver started. {"kind": "receiver", "name": "fluentforward", "pipeline": "logs"}
Dec 12 09:03:07 mlrt otelcol[164910]: 2022-12-12T09:03:07.731Z info pipelines/pipelines.go:102 Receiver is starting... {"kind": "receiver", "name": "otlp", "pipeline": "logs"}
Dec 12 09:03:07 mlrt otelcol[164910]: 2022-12-12T09:03:07.731Z info pipelines/pipelines.go:106 Receiver started. {"kind": "receiver", "name": "otlp", "pipeline": "logs"}
Dec 12 09:03:07 mlrt otelcol[164910]: 2022-12-12T09:03:07.731Z info pipelines/pipelines.go:102 Receiver is starting... {"kind": "receiver", "name": "signalfx", "pipeline": "logs"}
Dec 12 09:03:07 mlrt otelcol[164910]: 2022-12-12T09:03:07.731Z info pipelines/pipelines.go:106 Receiver started. {"kind": "receiver", "name": "signalfx", "pipeline": "logs"}
Dec 12 09:03:07 mlrt otelcol[164910]: 2022-12-12T09:03:07.731Z info pipelines/pipelines.go:102 Receiver is starting... {"kind": "receiver", "name": "smartagent/processlist", "pipeline": "logs"}
Dec 12 09:03:07 mlrt otelcol[164910]: 2022-12-12T09:03:07.731Z info pipelines/pipelines.go:106 Receiver started. {"kind": "receiver", "name": "smartagent/processlist", "pipeline": "logs"}
Dec 12 09:03:07 mlrt otelcol[164910]: 2022-12-12T09:03:07.731Z info healthcheck/handler.go:129 Health Check state change {"kind": "extension", "name": "health_check", "status": "ready"}
Dec 12 09:03:07 mlrt otelcol[164910]: 2022-12-12T09:03:07.731Z info service/service.go:106 Everything is ready. Begin running and processing data.
Everything is ready とあるので、初期処理は概ね大丈夫なようです！
ところが、今の環境ではなんかエラーログが出ています。
Dec 12 09:04:10 mlrt otelcol[164910]: 2022-12-12T09:04:10.139Z error exporterhelper/queued_retry.go:394 Exporting failed. The error is not retryable. Dropping data. {"kind": "exporter", "data_type": "logs", "name": "splunk_hec", "error": "Permanent error: \"HTTP/1.1 400 Bad Request\\r\\nContent-Length: 53\\r\\nContent-Type: text/plain; charset>
Dec 12 09:04:10 mlrt otelcol[164910]: go.opentelemetry.io/collector/exporter/exporterhelper.(*retrySender).send
Dec 12 09:04:10 mlrt otelcol[164910]: /builds/o11y-gdi/splunk-otel-collector-releaser/.go/pkg/mod/go.opentelemetry.io/collector@v0.66.0/exporter/exporterhelper/queued_retry.go:394
Dec 12 09:04:10 mlrt otelcol[164910]: go.opentelemetry.io/collector/exporter/exporterhelper.(*logsExporterWithObservability).send
Dec 12 09:04:10 mlrt otelcol[164910]: /builds/o11y-gdi/splunk-otel-collector-releaser/.go/pkg/mod/go.opentelemetry.io/collector@v0.66.0/exporter/exporterhelper/logs.go:134
Dec 12 09:04:10 mlrt otelcol[164910]: go.opentelemetry.io/collector/exporter/exporterhelper.(*queuedRetrySender).start.func1
Dec 12 09:04:10 mlrt otelcol[164910]: /builds/o11y-gdi/splunk-otel-collector-releaser/.go/pkg/mod/go.opentelemetry.io/collector@v0.66.0/exporter/exporterhelper/queued_retry.go:205
Dec 12 09:04:10 mlrt otelcol[164910]: go.opentelemetry.io/collector/exporter/exporterhelper/internal.(*boundedMemoryQueue).StartConsumers.func1
Dec 12 09:04:10 mlrt otelcol[164910]: /builds/o11y-gdi/splunk-otel-collector-releaser/.go/pkg/mod/go.opentelemetry.io/collector@v0.66.0/exporter/exporterhelper/internal/bounded_memory_queue.go:61
うーん、何か良からぬことが起こっていそう。このトラブルシュートは次回の課題とします。
OpenTelemetryの各言語エージェントやCollectorは、本番サービスのパフォーマンスボトルネックになることを避けるためか、テレメトリーデータの送信失敗に対して かなり相当あっさり諦める ようになっていて、さらに、この様子がメトリクスとして現れるとは限りません。なので、Collector自身のログも何らかの経路で収集してエラーログを見つける…ということが必要かもしれません。もちろん、ログ送信パイプライン自身が壊れている場合にはそれも無理なので、結局、古典的な方法に頼らざるを得ないポイントが出てくるというのが、計装を整えていくときのやっかいなところです。
とまあこんな感じに
Collectorの動きを確認する基本的なテレメトリーデータであるメトリクスとログについて紹介しました。ほかにもloggingエクスポーターやzpagez, pprofなど、テレメトリーデータ処理がつつがなく行われているかを調査するためのいくつかもの仕組みを備えています。公式ドキュメントのトラブルシュートガイド を覗いてみてください。
ということで、この記事は OpenTelemetry Advent Calendar 2022、12日目の記事でした。Have a happy instrumentation!
