LoginSignup
8
2

Delete article

Deleted articles cannot be recovered.

Draft of this article would be also deleted.

Are you sure you want to delete this article?

@rytsukain三菱電機株式会社 情報技術総合研究所 クラウド技術者コミュニティ

OpenTelemetryのlogsを試した

Posted at

目的

  • OpenTelemetryのlogsが2023年頃から安定版なってきたのでそろそろ試す

OpenTelemetryについて

OpenTelemetry1はシステムが可観測性を備えるためのメカニズム。
tracesやmetrics、logsといったテレメトリデータを計測したり、生成したり、
集めたり、他のシステムやアプリケーションに出力したりするためのフレームワーク。
ベンダー中立でオープンソース。OTelと略されることもある。

可観測性というのは、一言では表せない様々な要素を含んでいる。
ここでは割愛する。

OTel logsを試してみる

OTel logsのデータモデル2

目的

データモデルは次の3種類のログとイベントを適切に表現することを目的としている。

  • システム
    • OSが生成するログやイベントで、形式や内容などが変更できないもの。
    • 例えば、Syslog。
  • サードパーティ製アプリ
    • 形式や内容をカスタマイズできるもの。
    • 例えばApacheのログファイル。
  • 開発対象のアプリ
    • 必要に応じてソースコードを変更できるもの。

要求仕様

  • 既存のログ形式をマッピングできる。理想は可逆に変換できる。
  • マッピングは既存のログ形式が意図する内容を保存できる。

実装に影響する間接的な要求として以下がある。

  • データモデルのserialization/deserializationに必要なCPU使用率とデータ領域がある。

構造

JSONと同等の構造。

マッピング例

Otel logsの付録3では次のようなログのマッピング例が示されている。

  • RFC5424 Syslog
  • Windows Event Log
  • SignalFx Events
  • Splunk HEC
  • Log4j
  • Zap
  • Apache HTTP Server access log
  • CloudTrail Log Event
  • Google Cloud Logging
  • Elastic Common Schema

試した環境

アーキテクチャ

クライアントがエッジサーバを通してクラウドサービスにアクセスする構成を想定する。
エッジサーバのアクセスログをOpenTelemetryで取得してLokiに送信しGrafanaで参照する。
クラウドサービスはWebサーバとしてApache HTTP server、
エッジサーバはプロキシとしてApache HTTP server、
クライアントはApache Benchを用いる。

各構成要素はコンテナ。
下部に記載しているhttpd:2.4.62-alpine3.20などはコンテナイメージ。

実行環境

アーキテクチャに示した各構成要素はコンテナとして実行する。
ランタイムはDocker Desktopを用いた。

各種設定

docker-compose

コンテナの構成はdocker-composeで定義した。
各設定をvolumeでマウントしている。

compose.yaml 
services:
  service:
    image: "httpd:2.4.62-alpine3.20"
  edge:
    image: "httpd:2.4.62-alpine3.20"
    volumes:
      - "./edge/conf/httpd.conf:/usr/local/apache2/conf/httpd.conf:ro"
      - "logs:/usr/local/apache2/logs:rw"
  client:
    image: "httpd:2.4.62-alpine3.20"
  agent:
    image: "otel/opentelemetry-collector-contrib:0.108.0"
    volumes:
      - "./agent/otelcol-contrib/config.yaml:/etc/otelcol-contrib/config.yaml:ro"
      - "logs:/var/logs:ro"
  backend:
    image: "grafana/loki:3.1.1"
  viewer:
    image: "grafana/grafana:11.2.0"
    ports:
      - "3000:3000"
    volumes:
      - "./viewer/datasources/loki.yaml:/usr/share/grafana/conf/provisioning/datasources/loki.yaml:rw"
volumes:
  logs:

httpd.conf(edge)

エッジサーバのプロキシ設定は次の通り。
デフォルトからの変更点のみ記載している。

httpd.conf 
...

- #LoadModule proxy_module modules/mod_proxy.so
+ LoadModule proxy_module modules/mod_proxy.so
- #LoadModule proxy_connect_module modules/mod_proxy_connect.so
+ LoadModule proxy_connect_module modules/mod_proxy_connect.so
- #LoadModule proxy_http_module modules/mod_proxy_http.so
+ LoadModule proxy_http_module modules/mod_proxy_http.so

...

    #
    # If you prefer a logfile with access, agent, and referer information
    # (Combined Logfile Format) you can use the following directive.
    #
-     #CustomLog "logs/access_log" combined
+     CustomLog "logs/access_log" combined

...

+ # Forward Proxy
+ ProxyRequests On
+ ProxyVia On

config.yaml(agent)

エージェントのOTel設定は次の通り。
デフォルトからの変更点のみ記載している。

config.yaml 
# To limit exposure to denial of service attacks, change the host in endpoints below from 0.0.0.0 to a specific network interface.
# See https://github.com/open-telemetry/opentelemetry-collector/blob/main/docs/security-best-practices.md#safeguards-against-denial-of-service-attacks

extensions:
  health_check:
  pprof:
    endpoint: 0.0.0.0:1777
  zpages:
    endpoint: 0.0.0.0:55679

receivers:
-   otlp:
-     protocols:
-       grpc:
-         endpoint: 0.0.0.0:4317
-       http:
-         endpoint: 0.0.0.0:4318

-   opencensus:
-     endpoint: 0.0.0.0:55678

-   # Collect own metrics
-   prometheus:
-     config:
-       scrape_configs:
-       - job_name: 'otel-collector'
-         scrape_interval: 10s
-         static_configs:
-         - targets: ['0.0.0.0:8888']

-   jaeger:
-     protocols:
-       grpc:
-         endpoint: 0.0.0.0:14250
-       thrift_binary:
-         endpoint: 0.0.0.0:6832
-       thrift_compact:
-         endpoint: 0.0.0.0:6831
-       thrift_http:
-         endpoint: 0.0.0.0:14268

-   zipkin:
-     endpoint: 0.0.0.0:9411

+   filelog:
+     include: [ /var/logs/* ]
+     operators:
+       - type: regex_parser
+         # regex: '^(?P<client_address>.*) - - \[(?P<timestamp>.*) \+0000\] \"(?P<http_request_method>.*) (?P<url_full>.*) (?P<network_protocol_name>.*)/(?P<network_protocol_version>.*)\" (?P<http_response_status__code>[0-9]+) (?P<http_response_body_size>[0-9]+) \"\-\" \"(?P<user__agent_original>.*)\"'
+         regex: >-
+           ^(?P<client_address>.*)
+           -
+           -
+           \[(?P<timestamp>.*) \+0000\]
+           \"(?P<http_request_method>.*) (?P<url_full>.*) (?P<network_protocol_name>.*)/(?P<network_protocol_version>.*)\"
+           (?P<http_response_status__code>[0-9]+)
+           (?P<http_response_body_size>[0-9]+)
+           \"\-\"
+           \"(?P<user__agent_original>.*)\"
+         timestamp:
+           parse_from: attributes.timestamp
+           layout: '%d/%b/%Y:%H:%M:%S'
+       # - type: uri_parser
+       #   parse_from: attributes.url_full
+     attributes:
+       network.peer.address: edge


processors:
  batch:

+   transform:
+     log_statements:
+       - context: log
+         statements:
+           - replace_all_patterns(attributes, "key", "_", ".")
+           - replace_all_patterns(attributes, "key", "\\.\\.", "_")
+           - set(attributes["uuid"], UUID())
+           - append(body, values = [" ", attributes["uuid"]])

+   attributes:
+     actions:
+       - key: http.response.status_code
+         action: convert
+         converted_type: int
+       - key: http.response.body.size
+         action: convert
+         converted_type: int

exporters:
  debug:
    verbosity: detailed

+   otlphttp:
+     endpoint: http://backend:3100/otlp/

service:

  pipelines:

-     traces:
-       receivers: [otlp, opencensus, jaeger, zipkin]
-       processors: [batch]
-       exporters: [debug]

-     metrics:
-       receivers: [otlp, opencensus, prometheus]
-       processors: [batch]
-       exporters: [debug]

    logs:
-       receivers: [otlp]
+       receivers: [filelog]
-       processors: [batch]
+       processors: [transform, attributes]
-       exporters: [debug]
+       exporters: [debug, otlphttp]

  extensions: [health_check, pprof, zpages]

Loki-Grafana間

Grafanaの画面操作で接続する。
データソースにLokiを追加する。

  • Grafanaにログイン
  • データソースを追加
    • ページ左上のハンバーガメニュー(≡)を開く
      • Connections > Data sources
    • Add data sourceボタンをクリック
    • Lokiを選択
    • 接続先URLを設定
    • Save & testボタンをクリック
      • Data source successfully connected.と表示される

試した結果

ログを参照

クライアントからエッジサーバのプロキシ経由でクラウドサービスにアクセスする。

docker compose exec client sh -c 'ab -n 1 -X edge:80 http://service/'

エージェントのコンテナのログにOTelのデバッグログが出力される。
これをみてOTel設定のデバッグが行える。

OTelのデバッグログ 
2024-10-04 11:22:42 2024-10-04T02:22:42.259Z    info    LogsExporter    {"kind": "exporter", "data_type": "logs", "name": "debug", "resource logs": 1, "log records": 1}
2024-10-04 11:22:42 2024-10-04T02:22:42.260Z    info    ResourceLog #0
2024-10-04 11:22:42 Resource SchemaURL: 
2024-10-04 11:22:42 ScopeLogs #0
2024-10-04 11:22:42 ScopeLogs SchemaURL: 
2024-10-04 11:22:42 InstrumentationScope  
2024-10-04 11:22:42 LogRecord #0
2024-10-04 11:22:42 ObservedTimestamp: 2024-10-04 02:22:42.158415075 +0000 UTC
2024-10-04 11:22:42 Timestamp: 2024-10-04 02:22:42 +0000 UTC
2024-10-04 11:22:42 SeverityText: 
2024-10-04 11:22:42 SeverityNumber: Unspecified(0)
2024-10-04 11:22:42 Body: Slice(["172.21.0.7 - - [04/Oct/2024:02:22:42 +0000] \"GET http://service/ HTTP/1.0\" 200 45 \"-\" \"ApacheBench/2.3\""," ","cdf670a3-e469-41ed-8ee7-db42861d7abd"])
2024-10-04 11:22:42 Attributes:
2024-10-04 11:22:42      -> log.file.name: Str(access_log)
2024-10-04 11:22:42      -> network.protocol.version: Str(1.0)
2024-10-04 11:22:42      -> user_agent.original: Str(ApacheBench/2.3)
2024-10-04 11:22:42      -> client.address: Str(172.21.0.7)
2024-10-04 11:22:42      -> network.peer.address: Str(edge)
2024-10-04 11:22:42      -> url.full: Str(http://service/)
2024-10-04 11:22:42      -> network.protocol.name: Str(HTTP)
2024-10-04 11:22:42      -> http.response.body.size: Int(45)
2024-10-04 11:22:42      -> http.request.method: Str(GET)
2024-10-04 11:22:42      -> http.response.status_code: Int(200)
2024-10-04 11:22:42      -> timestamp: Str(04/Oct/2024:02:22:42)
2024-10-04 11:22:42      -> uuid: Str(cdf670a3-e469-41ed-8ee7-db42861d7abd)
2024-10-04 11:22:42 Trace ID: 
2024-10-04 11:22:42 Span ID: 
2024-10-04 11:22:42 Flags: 0
2024-10-04 11:22:42     {"kind": "exporter", "data_type": "logs", "name": "debug"}

ビューア(Grafana)でログを確認する。

  • ページ左上のハンバーガメニュー(≡)を開く
  • Exploreを選択
  • Label filtersで次を選ぶ
    • service_name = unknown_service
  • ページ右上のRun queryボタン(🔄)をクリック

以下1つ目の画面のようになればOK。
画面の1番下にログが表示されている。
>をクリックすると、2つ目の画面のように、
OTelで設定したフィールドが確認できる。

ログの表示

フィールドの表示

後述のハマったところに書いたように、
苦労してOTelのモデルにある項目名にマッピングしたが、
Grafanaで参照するとアンダースコア_になっている。
Grafana、Lokiどちらの仕様かは分からないが、
本題のOTelから外れることになるのでこれ以上は追わないことにする。

ログレコードの一覧表示でBody要素の文字列が同じレコードは1件しか出てこない。
1秒以内に複数件のログが存在しても表示されないことになる。
Grafana、Lokiどちらの仕様かは分からないが、
BodyにUUIDを足すことで1秒以内でも異なるレコードであると認識させることができた。
Grafana、Lokiどちらかの設定で解決できるかもしれないが、
本題のOTelから外れることになるのでこれ以上は追わないことにする。

バックエンド限界時の動作

バックエンドのコンテナを一時停止(pause)してからクライアントを動作させる。
クライアント-エッジサーバ-クラウドサービスの通信は問題なく成功する。

個人的にはCPU使用率を絞ってエージェントに503等が返るようにしたかったが、
compose fileの設定がうまく反映されなかったためpauseにした。

$ docker compose pause backend
[+] Pausing 1/0
 ✔ Container otel-log-retry-backend-1  Paused
$ docker compose exec client sh -c 'ab -n 1 -X edge:80 http://service/'
This is ApacheBench, Version 2.3 <$Revision: 1913912 $>
Copyright 1996 Adam Twiss, Zeus Technology Ltd, http://www.zeustech.net/
Licensed to The Apache Software Foundation, http://www.apache.org/

Benchmarking service [through edge:80] (be patient).....done


Server Software:        Apache/2.4.62
Server Hostname:        service
Server Port:            80

Document Path:          /
Document Length:        45 bytes

Concurrency Level:      1
Time taken for tests:   0.002 seconds
Complete requests:      1
Failed requests:        0
Total transferred:      310 bytes
HTML transferred:       45 bytes
Requests per second:    420.17 [#/sec] (mean)
Time per request:       2.380 [ms] (mean)
Time per request:       2.380 [ms] (mean, across all concurrent requests)
Transfer rate:          127.20 [Kbytes/sec] received

Connection Times (ms)
              min  mean[+/-sd] median   max
Connect:        0    0   0.0      0       0
Processing:     2    2   0.0      2       2
Waiting:        2    2   0.0      2       2
Total:          2    2   0.0      2       2

一方で、エージェントではOTelがログを取得するまでは成功しているが、
バックエンドが停止しているためタイムアウトで送信に失敗する。
その後、リトライ・タイムアウトを繰り返す。
リトライをいつまでするか、は設定事項で、デフォルトは5分。
そのため、5分以上バックエンドが停止しているとテレメトリデータが欠損する。

OTelのログ 
2024-11-13 16:02:52 2024-11-13T07:02:52.965Z    info    LogsExporter    {"kind": "exporter", "data_type": "logs", "name": "debug", "resource logs": 1, "log records": 1}
2024-11-13 16:02:52 2024-11-13T07:02:52.965Z    info    ResourceLog #0
2024-11-13 16:02:52 Resource SchemaURL: 
2024-11-13 16:02:52 ScopeLogs #0
2024-11-13 16:02:52 ScopeLogs SchemaURL: 
2024-11-13 16:02:52 InstrumentationScope  
2024-11-13 16:02:52 LogRecord #0
2024-11-13 16:02:52 ObservedTimestamp: 2024-11-13 07:02:52.865935643 +0000 UTC
2024-11-13 16:02:52 Timestamp: 2024-11-13 07:02:52 +0000 UTC
2024-11-13 16:02:52 SeverityText: 
2024-11-13 16:02:52 SeverityNumber: Unspecified(0)
2024-11-13 16:02:52 Body: Slice(["172.21.0.6 - - [13/Nov/2024:07:02:52 +0000] \"GET http://service/ HTTP/1.0\" 200 45 \"-\" \"ApacheBench/2.3\""," ","ce390cdf-c7df-471a-a1bc-9c07d75c5144"])
2024-11-13 16:02:52 Attributes:
2024-11-13 16:02:52      -> client.address: Str(172.21.0.6)
2024-11-13 16:02:52      -> http.request.method: Str(GET)
2024-11-13 16:02:52      -> user_agent.original: Str(ApacheBench/2.3)
2024-11-13 16:02:52      -> url.full: Str(http://service/)
2024-11-13 16:02:52      -> http.response.status_code: Int(200)
2024-11-13 16:02:52      -> log.file.name: Str(access_log)
2024-11-13 16:02:52      -> network.protocol.version: Str(1.0)
2024-11-13 16:02:52      -> timestamp: Str(13/Nov/2024:07:02:52)
2024-11-13 16:02:52      -> network.protocol.name: Str(HTTP)
2024-11-13 16:02:52      -> http.response.body.size: Int(45)
2024-11-13 16:02:52      -> network.peer.address: Str(edge)
2024-11-13 16:02:52      -> uuid: Str(ce390cdf-c7df-471a-a1bc-9c07d75c5144)
2024-11-13 16:02:52 Trace ID: 
2024-11-13 16:02:52 Span ID: 
2024-11-13 16:02:52 Flags: 0
2024-11-13 16:02:52     {"kind": "exporter", "data_type": "logs", "name": "debug"}
2024-11-13 16:03:22 2024-11-13T07:03:22.965Z    info    exporterhelper/retry_sender.go:118      Exporting failed. Will retry the request after interval.        {"kind": "exporter", "data_type": "logs", "name": "otlphttp", "error": "failed to make an HTTP request: Post \"http://backend:3100/otlp/v1/logs\": context deadline exceeded (Client.Timeout exceeded while awaiting headers)", "interval": "3.28785794s"}
2024-11-13 16:03:56 2024-11-13T07:03:56.253Z    info    exporterhelper/retry_sender.go:118      Exporting failed. Will retry the request after interval.        {"kind": "exporter", "data_type": "logs", "name": "otlphttp", "error": "failed to make an HTTP request: Post \"http://backend:3100/otlp/v1/logs\": context deadline exceeded (Client.Timeout exceeded while awaiting headers)", "interval": "4.243307282s"}
2024-11-13 16:04:30 2024-11-13T07:04:30.495Z    info    exporterhelper/retry_sender.go:118      Exporting failed. Will retry the request after interval.        {"kind": "exporter", "data_type": "logs", "name": "otlphttp", "error": "failed to make an HTTP request: Post \"http://backend:3100/otlp/v1/logs\": context deadline exceeded (Client.Timeout exceeded while awaiting headers)", "interval": "7.931756782s"}
2024-11-13 16:05:08 2024-11-13T07:05:08.425Z    info    exporterhelper/retry_sender.go:118      Exporting failed. Will retry the request after interval.        {"kind": "exporter", "data_type": "logs", "name": "otlphttp", "error": "failed to make an HTTP request: Post \"http://backend:3100/otlp/v1/logs\": context deadline exceeded (Client.Timeout exceeded while awaiting headers)", "interval": "18.230287756s"}
2024-11-13 16:05:56 2024-11-13T07:05:56.731Z    info    exporterhelper/retry_sender.go:118      Exporting failed. Will retry the request after interval.        {"kind": "exporter", "data_type": "logs", "name": "otlphttp", "error": "failed to make an HTTP request: Post \"http://backend:3100/otlp/v1/logs\": context deadline exceeded (Client.Timeout exceeded while awaiting headers)", "interval": "18.587565785s"}
2024-11-13 16:06:45 2024-11-13T07:06:45.317Z    info    exporterhelper/retry_sender.go:118      Exporting failed. Will retry the request after interval.        {"kind": "exporter", "data_type": "logs", "name": "otlphttp", "error": "failed to make an HTTP request: Post \"http://backend:3100/otlp/v1/logs\": context deadline exceeded (Client.Timeout exceeded while awaiting headers)", "interval": "37.434242827s"}
2024-11-13 16:07:52 2024-11-13T07:07:52.746Z    error   exporterhelper/queue_sender.go:92       Exporting failed. Dropping data.       {"kind": "exporter", "data_type": "logs", "name": "otlphttp", "error": "no more retries left: failed to make an HTTP request: Post \"http://backend:3100/otlp/v1/logs\": context deadline exceeded (Client.Timeout exceeded while awaiting headers)", "dropped_items": 1}
2024-11-13 16:07:52 go.opentelemetry.io/collector/exporter/exporterhelper.newQueueSender.func1
2024-11-13 16:07:52     go.opentelemetry.io/collector/exporter@v0.108.1/exporterhelper/queue_sender.go:92
2024-11-13 16:07:52 go.opentelemetry.io/collector/exporter/internal/queue.(*boundedMemoryQueue[...]).Consume
2024-11-13 16:07:52     go.opentelemetry.io/collector/exporter@v0.108.1/internal/queue/bounded_memory_queue.go:52
2024-11-13 16:07:52 go.opentelemetry.io/collector/exporter/internal/queue.(*Consumers[...]).Start.func1
2024-11-13 16:07:52     go.opentelemetry.io/collector/exporter@v0.108.1/internal/queue/consumers.go:43

エージェント限界時の動作

クライアント-エッジサーバ-クラウドサービス間は10,000リクエストでも特に問題なし。

$ docker compose exec client sh -c 'ab -n 10000 -X edge:80 http://service/'
This is ApacheBench, Version 2.3 <$Revision: 1913912 $>
Copyright 1996 Adam Twiss, Zeus Technology Ltd, http://www.zeustech.net/
Licensed to The Apache Software Foundation, http://www.apache.org/

Benchmarking service [through edge:80] (be patient)
Completed 1000 requests
Completed 2000 requests
Completed 3000 requests
Completed 4000 requests
Completed 5000 requests
Completed 6000 requests
Completed 7000 requests
Completed 8000 requests
Completed 9000 requests
Completed 10000 requests
Finished 10000 requests


Server Software:        Apache/2.4.62
Server Hostname:        service
Server Port:            80

Document Path:          /
Document Length:        45 bytes

Concurrency Level:      1
Time taken for tests:   18.719 seconds
Complete requests:      10000
Failed requests:        0
Total transferred:      3100000 bytes
HTML transferred:       450000 bytes
Requests per second:    534.20 [#/sec] (mean)
Time per request:       1.872 [ms] (mean)
Time per request:       1.872 [ms] (mean, across all concurrent requests)
Transfer rate:          161.72 [Kbytes/sec] received

Connection Times (ms)
              min  mean[+/-sd] median   max
Connect:        0    0   0.1      0       7
Processing:     1    2   1.3      1      29
Waiting:        0    2   1.3      1      29
Total:          1    2   1.3      1      29

Percentage of the requests served within a certain time (ms)
  50%      1
  66%      2
  75%      2
  80%      2
  90%      3
  95%      3
  98%      5
  99%      7
 100%     29 (longest request)

ログの取得から表示も特に問題なかったので、
エージェントのメモリをギリギリまで制限する。
コンテナのメモリを少なくしていくとexit code 137で落ちるようになる。
メモリ不足のコードのようなので概ね意図通り。
Exited(137)状態のエージェントコンテナをstartで再び動かしても、
未送信のログは送信されず。

compose.yamlの変更箇所 
  agent:
    image: "otel/opentelemetry-collector-contrib:0.108.0"
+    deploy:
+      resources:
+        limits:
+          memory: 30M
    volumes:
      - "./agent/otelcol-contrib/config.yaml:/etc/otelcol-contrib/config.yaml:ro"
      - "logs:/var/logs:ro"

コンテナの終了コード。

exited with code 137

ログファイルを先頭から読み直すオプションがあった(start_at)4。
OTelの仕様ではログレコードが重複することはある5、という記述はあったので、
大量に重複するかもしれないが仕様上は問題ない。
テレメトリデータの欠損がなくなると期待して設定した。

config.yamlの変更箇所 
receivers:
  filelog:
    include: [ /var/logs/* ]
+    start_at: beginning
    operators:
      - type: regex_parser

クライアントを動作させた結果、エージェントでは次のようなログが出力された。
400が返ってきてテレメトリデータが欠損している。

2024-11-14 09:55:04 2024-11-14T00:55:04.922Z    error   exporterhelper/queue_sender.go:92       Exporting failed. Dropping data.        {"kind": "exporter", "data_type": "logs", "name": "otlphttp", "error": "not retryable error: Permanent error: rpc error: code = InvalidArgument desc = error exporting items, request to http://backend:3100/otlp/v1/logs responded with HTTP Status Code 400", "dropped_items": 14}
2024-11-14 09:55:04 go.opentelemetry.io/collector/exporter/exporterhelper.newQueueSender.func1
2024-11-14 09:55:04     go.opentelemetry.io/collector/exporter@v0.108.1/exporterhelper/queue_sender.go:92
2024-11-14 09:55:04 go.opentelemetry.io/collector/exporter/internal/queue.(*boundedMemoryQueue[...]).Consume
2024-11-14 09:55:04     go.opentelemetry.io/collector/exporter@v0.108.1/internal/queue/bounded_memory_queue.go:52
2024-11-14 09:55:04 go.opentelemetry.io/collector/exporter/internal/queue.(*Consumers[...]).Start.func1
2024-11-14 09:55:04     go.opentelemetry.io/collector/exporter@v0.108.1/internal/queue/consumers.go:43

バックエンドのログは次のように出力されていた。
これを見ると、timestampが古すぎるとある。Lokiでは1週間以内が目安のようだ。
確かに古い情報をどこまで信用してよいか、という要件がバックエンド側に存在してもおかしくない。
また、しばらくするとエージェントは137で終了した。メモリ不足はどうしようもないと分かった。

2024-11-14 09:55:04 level=error ts=2024-11-14T00:55:04.22610842Z caller=manager.go:49 component=distributor path=write msg="write operation failed" details="entry for stream '{service_name=\"unknown_service\"}' has timestamp too old: 2024-09-11T06:51:03Z, oldest acceptable timestamp is: 2024-11-07T00:55:04Z" org_id=fake

耐障害性を高める使い方

エージェントの動作に必要なCPUやメモリ等のリソース割当があったとしても、
ハードウェア障害などによるログ欠損のリスクは残る。
障害から復帰する際にはエージェントが再起動することになる。
OTelのリポジトリでは、再起動の影響を最小限にする構成例が紹介されている6。
例として紹介されていたのは次の2つ。

  • filestorage
    • ログ読み込みを再開する位置の記録
  • exporterhelper persistent-queue
    • バックエンドへの送信が未処理のログの記録

最新のドキュメント7ではcreate_directoryオプションがあったが、
今回使ったコンテナイメージ(0.108.0)では未実装だった。
そのため、compose.yaml等でディレクトリを作成しておく必要がある。

docker composeでvolumeを作成する(dockerホストがディレクトリを作成する)場合は
所有者がrootになることに注意が必要。
agentはroot以外のユーザで動作しているのでpermission deniedが発生して起動しない。
compose.yamlのサブディレクトリなどをマウントするようにし、
所有権が10001:0になるようにしておく。

試しにメモリが足りない状態でfilestorageのオプションを有効にしてみた。
メモリが足りないので、LogRecord #98で落ちた。
リスタートしても変わらず。
ストレージの記録を確認したところ、オフセットがほとんど進んでいなかった。
短時間に起動/終了を繰り返すと同じログが無限に続くかもしれない。

2024-12-03 15:37:38 LogRecord #98
2024-12-03 15:37:38 ObservedTimestamp: 2024-12-03 06:37:38.180445545 +0000 UTC
2024-12-03 15:37:38 Timestamp: 2024-12-03 06:37:38 +0000 UTC
2024-12-03 15:37:38 SeverityText: 
2024-12-03 15:37:38 SeverityNumber: Unspecified(0)
2024-12-03 15:37:38 Body: Slice(["172.21.0.5 - - [03/Dec/2024:06:37:38 +0000] \"GET http://service/ HTTP/1.0\" 200 45 \"-\" \"ApacheBench/2.3\""," ","50daf975-b1eb-4302-b78c-8c3f44af2ff5"])
2024-12-03 15:37:38 Attributes:
2024-12-03 15:37:38      -> network.peer.address: Str(edge)
2024-12-03 15:37:38      -> http.request.method: Str(GET)
2024-12-03 15:37:38      -> network.protocol.name: Str(HTTP)
2024-12-03 15:37:38      -> url.full: Str(http://service/)
2024-12-03 15:37:38      -> log.file.name: Str(access_log)
2024-12-03 15:37:38      -> timestamp: Str(03/Dec/2024:06:37:38)
2024-12-03 15:37:38      -> user_agent.original: Str(ApacheBench/2.3)
2024-12-03 15:37:38      -> client.address: Str(172.21.0.5)
2024-12-03 15:37:38      -> network.protocol.version: Str(1.0)
2024-12-03 15:37:38      -> http.response.status_code: Int(200)
2024-12-03 15:37:38      -> http.response.body.size: Int(45)
2024-12-03 15:37:38      -> uuid: Str(50daf975-b1eb-4302-b78c-8c3f44af2ff5)
2024-12-03 15:37:38 Trace ID: 
2024-12-03 15:37:38 Span ID: 
2024-12-03 15:37:38 Flags: 0
2024-12-03 15:37:38     {"kind": "exporter", "data_type": "logs", "name": "debug"}

まとめ

  • 簡単に試すことはできた。*.logをある程度同じ形式でかき集めるのは楽になりそう。
  • OTel logsへの形式のマッピングは凝ると時間を取られる。分かれば良し、くらいに思ったほうが良さそう。
  • 絶対に欠損させない、はおそらく無理(or困難)で、
    バックエンドの仕様も踏まえつつ、どういったときに欠損するか、を知っておくのが重要と感じた。

その他

ハマったところ

ApacheのアクセスログとOTelの項目名とのマッピング

Apacheのアクセスログは次のような出力。

172.21.0.2 - - [11/Sep/2024:21:14:12 +0000] "GET http://service/ HTTP/1.0" 200 45 "-" "ApacheBench/2.3"

これをOTelのモデルにある項目名にマッピングする必要がある。
dockerのvolume経由でログファイルを参照できるようにしているので、
OTelのreceiverはfilelogreceiver8を使う。

filelogreceiverでは一行の処理に複数のoperatorを定義できる。
Apacheのアクセスログ専用のoperatorは見当たらなかった。
おそらく、Apacheの設定で項目が変えられるためと考えられる。
そのため、正規表現で処理するoperatorであるregex_parer9を利用した。

正規表現では名前付きのキャプチャグループがそのままOTelの項目にマッピングされる。
しかし、OTelで推奨される項目名http.response.status_codeなどにはマッピングできないことが分かった。
原因は、キャプチャグループの名前にドット.が使えないことであった。
ドット.を使うためのエスケープシーケンスなども調査したが、存在しないようであった。

直接解決する手段が見つからなかったため、OTelの他のoperatorを組み合わせることで、
OTelの項目名に一致させることとした。

  • 項目名をマップに従って変換
    • 特定の項目名を指定した項目名でコピー、削除のようなoperatorの組み合わせでOTelの項目に一致させることができる。
    • ただし、項目が増えるたびにメンテナンスが必要になるため採用しなかった。
  • 項目名の一部を置換してOTelの項目名に変換
    • receiver後のprocessorで処理する。
    • transformには文字の置換など様々な組み込み関数が用意されている。
    • キャプチャグループの名前に、ドット.の代わりにアンダースコア_を用いた。
    • アンダースコア_をドット.に置換する処理でOTelの項目名に一致させた。
    • 項目が増えてもメンテナンスが不要なため採用した。

これで次のようにマッピングできた。
regex_parserは全て文字列として値を取得するため、
ステータスコードやバイト数などはprocessorのattributesで型変換も行っている。

OTelのログ 
LogRecord #65
ObservedTimestamp: 2024-09-11 23:59:40.074562537 +0000 UTC
Timestamp: 2024-09-11 23:59:40 +0000 UTC
SeverityText: 
SeverityNumber: Unspecified(0)
Body: Str(172.21.0.2 - - [11/Sep/2024:23:59:40 +0000] \"GET http://service/ HTTP/1.0\" 200 45 \"-\" \"ApacheBench/2.3\")
Attributes:
     -> http.request.method: Str(GET)
     -> network.protocol.version: Str(1.0)
     -> http.response.body.size: Int(45)
     -> network.peer.address: Str(edge)
     -> client.address: Str(172.21.0.2)
     -> http.response.status_code: Int(200)
     -> network.protocol.name: Str(HTTP)
     -> user_agent.original: Str(ApacheBench/2.3)
     -> log.file.name: Str(access_log)
     -> timestamp: Str(11/Sep/2024:23:59:40)
     -> url.full: Str(http://service/)
Trace ID: 
Span ID: 
Flags: 0
    {"kind": "exporter", "data_type": "logs", "name": "debug"}

  1. https://opentelemetry.io/ ↩

  2. https://opentelemetry.io/docs/specs/otel/logs/data-model/ ↩

  3. https://opentelemetry.io/docs/specs/otel/logs/data-model-appendix/ ↩

  4. https://github.com/open-telemetry/opentelemetry-collector-contrib/tree/main/receiver/filelogreceiver#configuration ↩

  5. https://opentelemetry.io/docs/specs/otlp/#duplicate-data ↩

  6. https://github.com/open-telemetry/opentelemetry-collector-contrib/tree/main/examples/fault-tolerant-logs-collection ↩

  7. https://github.com/open-telemetry/opentelemetry-collector-contrib/tree/main/extension/storage/filestorage ↩

  8. https://github.com/open-telemetry/opentelemetry-collector-contrib/tree/main/receiver/filelogreceiver ↩

  9. https://github.com/open-telemetry/opentelemetry-collector-contrib/blob/main/pkg/stanza/docs/operators/regex_parser.md ↩

8
2
0

Register as a new user and use Qiita more conveniently

  1. You get articles that match your needs
  2. You can efficiently read back useful information
  3. You can use dark theme
What you can do with signing up
Sign upLogin
8
2

Delete article

Deleted articles cannot be recovered.

Draft of this article would be also deleted.

Are you sure you want to delete this article?