Article:

今まで自宅サーバーのwebは個人的なページのみで外部の方に使ってもらうことはなかったのですが、最近misskeyサーバーを自宅でホストしてみたのでその監視の追加が急務でした。

自宅では様々なサブドメイン宛の通信をapacheでつくったproxyサーバーが配分しているので、「それぞれのサブドメイン(サービス)ごとに」「どんなhttpステータスの通信がどれくらい行われていて」「レスポンスタイムがだいたいどれくらいなのか」を簡単にチェックできると良いですね。

apache exporterなどの既存のexporterを使うこともできますが、これはサービスごとにメトリクスが取れない上に、新しいexporterを別途インストールするわずらわしさもあります。

Gammalabではログ集約にpromtailを使っているのですが、promtailはただログをlokiに送信するだけでなく、収集したログに対して様々な処理を行った上で、ログだけでなくGaugeやCounterやHistogramなどのメトリクスとしてprometheus がスクレイプできる形式で公開できる機能もあります。

なので今回はpromtailの設定を行ってapacheのログを読み、メトリクスとして公開する方法をまとめようと思います。

今回作ったダッシュボードはこんな感じです。

apache2側の設定変更

apache2ではデフォルトで用意されているLogFormatにはレスポンスタイムが含まれていません。 なので今回promtailで解析する用に新しくフォーマットを定義しようと思います。

また、virtualhostごとにログファイルを別出ししようと思います(これはtotegammaの趣味)。

logformatを追加

apache.conf
1

LogFormat "%a %t \"%r\" %>s %O \"%{Referer}i\" \"%{User-Agent}i\" %D" promtail_compatible

%Dがマイクロ秒単位のレスポンスタイムになります。

virtualhostごとにログを出す

雑に記述するとこういう系です。

apache.conf
1
2
3
4
5
6

<VirtualHost *:443>
  ServerName yourservice.yourdomain.tld
  ...
  CustomLog ${APACHE_LOG_DIR}/yourservice_access.log promtail_compatible
  ErrorLog ${APACHE_LOG_DIR}/yourservice_error.log
</VirtualHost>

promtailのpipelineを設定する

今回の主役のpromtailですね。 全体としてはこんな感じになります。

promtail.yml
 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55

server:
  http_listen_port: 9080
  grpc_listen_port: 0

positions:
  filename: /tmp/positions.yaml

clients:
  - url: <your loki address>

scrape_configs:
- job_name: apache_access
  static_configs:
  - targets:
      - localhost
    labels:
      job: apache_access
      __path__: /var/log/apache2/*_access.log
  pipeline_stages:
    - match:
        selector: '{job="apache_access"}'
        stages:
        - regex:
           source: filename
           expression: '^.*/(?P<service>.*?)_access.log$'
        - labels:
             service:
    - regex:
        expression: '^(?P<ip>.*?) \[(?P<date>.*?) (?P<timezone>.*?)\] \"(?P<request_method>.*?) (?P<path>.*?) (?P<request_version>HTTP/.*)?\" (?P<status>.*?) (?P<length>.*?) \"(?P<referrer>.*?)\" \"(?P<user_agent>.*?)\" (?P<response_time>.*)$'

    - metrics:
        http_request_duration_ms_sum:
          type: Counter
          description: total response time
          source: response_time
          config:
            action: add
    - metrics:
        http_request_count:
          type: Counter
          max_idle_duration: 24h
          description: http_request_count by response status
          config:
            match_all: true
            action: inc
    - labels:
        status:
    - metrics:
        http_request_count_by_status:
          type: Counter
          max_idle_duration: 24h
          description: http_request_count by response status
          source: status
          config:
            action: inc

主役はpipeline_stagesの部分ですね。抜粋して見ていきましょう。

filenameをラベルに

promtail.yml (抜粋)
1
2
3
4
5
6
7
8

 - match:
     selector: '{job="apache_access"}'
     stages:
     - regex:
        source: filename
        expression: '^.*/(?P<service>.*?)_access.log$'
     - labels:
          service:

これは前座ですね。ファイル名の一部をサービスタグに変換しています。 最終的に生成されるメトリクスを見るとfilenameというラベルがあるので、それでrelabel_configすればいいじゃん！という気持ちになったのですが、 なんかfilenameラベルはrelabel_configの処理が行われた後に発生するらしく、使えなかったのでこうやってちょっと無理くり変換しています。

apacheログのパース

promtail.yml (抜粋)
1
2

- regex:
    expression: '^(?P<ip>.*?) \[(?P<date>.*?) (?P<timezone>.*?)\] \"(?P<request_method>.*?) (?P<path>.*?) (?P<request_version>HTTP/.*)?\" (?P<status>.*?) (?P<length>.*?) \"(?P<referrer>.*?)\" \"(?P<user_agent>.*?)\" (?P<response_time>.*)$'

超大事な部分ですね。regexステージを使って、ログをパースして変数として出しています。

メトリクス生成(1)

promtail.yml (抜粋)
 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13
14
15

- metrics:
    http_request_duration_ms_sum:
      type: Gauge
      description: total response time
      source: response_time
      config:
        action: add
- metrics:
    http_request_count:
      type: Counter
      max_idle_duration: 24h
      description: http_request_count by response status
      config:
        match_all: true
        action: inc

metricsステージを使ってメトリクスとして実際に外出ししている部分です。 ここでは、リクエスト回数の総計と、レスポンスタイムの総計を出しています。

action: addは、直前ので選択しているsource: response_timeをどんどん累積していけという指定です。

一方次のaction: incは、内容にかかわらず来たログの行数分インクリメントしろという指定になります。

メトリクス生成(2)

promtail.yml (抜粋)
 1
 2
 3
 4
 5
 6
 7
 8
 9
10

- labels:
    status:
- metrics:
    http_request_count_by_status:
      type: Counter
      max_idle_duration: 24h
      description: http_request_count by response status
      source: status
      config:
        action: inc

最初にlabelsステージでstatusの値をラベル化しています。こうすることで、これ以降作られるメトリクスはこのラベルの値でさらに分割されるようになります。 この後にもう一度リクエストカウントを生成するmetricsステージを置くことで、欲しかった「HTTPステータスごとのリクエスト回数」を計測することができます。

ここまでできたらpromtailをrestartしましょう。localhost:9080/metricsにアクセスすると、パイプラインで指定したメトリクスが生成されていることを確認できるはずです。

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41

# HELP promtail_custom_http_request_count http_request_count by response status
# TYPE promtail_custom_http_request_count counter
promtail_custom_http_request_count{filename="/var/log/apache2/elastic_access.log",job="apache_access",service="elastic"} 29474
promtail_custom_http_request_count{filename="/var/log/apache2/fluffy_social_access.log",job="apache_access",service="fluffy_social"} 175330
promtail_custom_http_request_count{filename="/var/log/apache2/grafana_access.log",job="apache_access",service="grafana"} 17489
promtail_custom_http_request_count{filename="/var/log/apache2/sse-relay_access.log",job="apache_access",service="sse-relay"} 11
promtail_custom_http_request_count{filename="/var/log/apache2/teleport_access.log",job="apache_access",service="teleport"} 236
# HELP promtail_custom_http_request_count_by_status http_request_count by response status
# TYPE promtail_custom_http_request_count_by_status counter
promtail_custom_http_request_count_by_status{filename="/var/log/apache2/elastic_access.log",job="apache_access",service="elastic",status="200"} 23751
promtail_custom_http_request_count_by_status{filename="/var/log/apache2/elastic_access.log",job="apache_access",service="elastic",status="201"} 5667
promtail_custom_http_request_count_by_status{filename="/var/log/apache2/elastic_access.log",job="apache_access",service="elastic",status="502"} 56
promtail_custom_http_request_count_by_status{filename="/var/log/apache2/fluffy_social_access.log",job="apache_access",service="fluffy_social",status="200"} 161868
promtail_custom_http_request_count_by_status{filename="/var/log/apache2/fluffy_social_access.log",job="apache_access",service="fluffy_social",status="202"} 6295
promtail_custom_http_request_count_by_status{filename="/var/log/apache2/fluffy_social_access.log",job="apache_access",service="fluffy_social",status="204"} 934
promtail_custom_http_request_count_by_status{filename="/var/log/apache2/fluffy_social_access.log",job="apache_access",service="fluffy_social",status="206"} 387
promtail_custom_http_request_count_by_status{filename="/var/log/apache2/fluffy_social_access.log",job="apache_access",service="fluffy_social",status="301"} 4665
promtail_custom_http_request_count_by_status{filename="/var/log/apache2/fluffy_social_access.log",job="apache_access",service="fluffy_social",status="302"} 528
promtail_custom_http_request_count_by_status{filename="/var/log/apache2/fluffy_social_access.log",job="apache_access",service="fluffy_social",status="304"} 4
promtail_custom_http_request_count_by_status{filename="/var/log/apache2/fluffy_social_access.log",job="apache_access",service="fluffy_social",status="400"} 27
promtail_custom_http_request_count_by_status{filename="/var/log/apache2/fluffy_social_access.log",job="apache_access",service="fluffy_social",status="403"} 1
promtail_custom_http_request_count_by_status{filename="/var/log/apache2/fluffy_social_access.log",job="apache_access",service="fluffy_social",status="404"} 550
promtail_custom_http_request_count_by_status{filename="/var/log/apache2/fluffy_social_access.log",job="apache_access",service="fluffy_social",status="415"} 5
promtail_custom_http_request_count_by_status{filename="/var/log/apache2/fluffy_social_access.log",job="apache_access",service="fluffy_social",status="422"} 11
promtail_custom_http_request_count_by_status{filename="/var/log/apache2/fluffy_social_access.log",job="apache_access",service="fluffy_social",status="429"} 2
promtail_custom_http_request_count_by_status{filename="/var/log/apache2/fluffy_social_access.log",job="apache_access",service="fluffy_social",status="500"} 21
promtail_custom_http_request_count_by_status{filename="/var/log/apache2/fluffy_social_access.log",job="apache_access",service="fluffy_social",status="503"} 31
promtail_custom_http_request_count_by_status{filename="/var/log/apache2/grafana_access.log",job="apache_access",service="grafana",status="200"} 17454
promtail_custom_http_request_count_by_status{filename="/var/log/apache2/grafana_access.log",job="apache_access",service="grafana",status="304"} 30
promtail_custom_http_request_count_by_status{filename="/var/log/apache2/grafana_access.log",job="apache_access",service="grafana",status="404"} 1
promtail_custom_http_request_count_by_status{filename="/var/log/apache2/grafana_access.log",job="apache_access",service="grafana",status="503"} 4
promtail_custom_http_request_count_by_status{filename="/var/log/apache2/sse-relay_access.log",job="apache_access",service="sse-relay",status="200"} 10
promtail_custom_http_request_count_by_status{filename="/var/log/apache2/sse-relay_access.log",job="apache_access",service="sse-relay",status="404"} 1
promtail_custom_http_request_count_by_status{filename="/var/log/apache2/teleport_access.log",job="apache_access",service="teleport",status="200"} 232
promtail_custom_http_request_count_by_status{filename="/var/log/apache2/teleport_access.log",job="apache_access",service="teleport",status="302"} 4
# HELP promtail_custom_http_request_duration_ms_sum total response time
# TYPE promtail_custom_http_request_duration_ms_sum gauge
promtail_custom_http_request_duration_ms_sum{filename="/var/log/apache2/elastic_access.log",job="apache_access",service="elastic"} 7.48008252e+08
promtail_custom_http_request_duration_ms_sum{filename="/var/log/apache2/fluffy_social_access.log",job="apache_access",service="fluffy_social"} 4.561310205e+11
promtail_custom_http_request_duration_ms_sum{filename="/var/log/apache2/grafana_access.log",job="apache_access",service="grafana"} 5.43702246e+08
# HELP promtail_dropped_bytes_total Number of bytes dropped because failed to be sent to the ingester after all retries.

ダッシュボードの作成

あとはダッシュボードを作成するだけですね！ 2xxのステータスだけを抽出するには、regexでラベルを絞り込むと良いですね。

2xx count
1

sum by (service) (rate(promtail_custom_http_request_count_by_status{status=~"2[0-9][0-9]"}[$__rate_interval]))

レスポンスタイムの平均は、レスポンスタイムの合計の増量 / リクエスト回数の合計の増量で算出できますね。

Latency (seconds)
1

(sum by (service)(rate(promtail_custom_http_request_duration_ms_sum[$__rate_interval])) / sum by (service)(rate(promtail_custom_http_request_count[$__rate_interval])))/1000000

これで完成です！！

websocket対策

つくったダッシュボードを眺めていると、なんか突然レスポンスタイムが5分とかのスパイクが発生していることに気づきました。

僕が「ン！？！？！？！」って騒いでいるとその時VCにいたここあ天才博士が「websocketでは？」とつぶやいてくれてそれだ！！！となりました。

websocketはUpgrade: websocketヘッダーのついたリクエストに対して、101 Switching Protocolsレスポンスを返すことで成立しますが、このwebsocketの通信が終了した際にこの通信が確立されていた時間を抱えた200レスポンスが返るようです。コマッタ。

かなしい
1

IP [26/Mar/2023:11:03:21 +0000] "GET /streaming HTTP/1.1" 200 4936 "-" "UA" 613973554

なんとかこれだけ除外できないかなぁという感じですよね。仕方がないので、とりあえずUpdateヘッダがついているリクエストはノーカンにすることにしましょう。

まず、apacheのlogformatにリクエストのUpgradeヘッダの内容を落とすように追加します。

apache.conf
1

LogFormat "%a %t \"%r\" %>s %O %{Upgrade}o \"%{Referer}i\" \"%{User-Agent}i\" %D" promtail_compatible

そして、pipeline_stagesを次のように編集しました。

promtail.yml
 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44

pipeline_stages:
  - match:
      selector: '{job="apache_access"}'
      stages:
      - regex:
         source: filename
         expression: '^.*/(?P<service>.*?)_access.log$'
      - labels:
           service:
  - regex:
      expression: '^(?P<ip>.*?) \[(?P<date>.*?) (?P<timezone>.*?)\] \"(?P<request_method>.*?) (?P<path>.*?) (?P<request_version>HTTP/.*)?\" (?P<status>.*?) (?P<length>.*?) (?P<upgrade>.*?) \"(?P<referrer>.*?)\" \"(?P<user_agent>.*?)\" (?P<response_time>.*)$'

  - labels:
      upgrade:
  - match:
      selector: '{upgrade="-"}'
      stages:
      - labeldrop:
          - upgrade
      - metrics:
          http_request_duration_ms_sum:
            type: Gauge
            description: total response time
            source: response_time
            config:
              action: add
      - metrics:
          http_request_count:
            type: Counter
            max_idle_duration: 24h
            description: http_request_count by response status
            config:
              match_all: true
              action: inc
      - labels:
          status:
      - metrics:
          http_request_count_by_status:
            type: Counter
            max_idle_duration: 24h
            description: http_request_count by response status
            source: status
            config:
              action: inc

matchステージでupgradeの内容をチェックしています。dropしても良いのですが、ログとしては残したいのでこういう形です。

1つ気になるのが、ラベル化せずに条件分岐する方法はないのかな…?という感じです。このために一度upgradeラベルをlabelsステージで作成し、matchステージでその内容を見た直後にlabeldropしています。が、いい感じの方法はないかなぁ…。

これで一旦はwebsocketによって本当に知りたいレスポンスタイムが汚染されることを防ぐことができました。が、今回websocketだけをケアしましたが、他にもロングポーリングやServer-Sent Eventsなども個別にケアしてあげる必要がありますね。オンオン(泣き声)。

それについてはまた必要になったら追記しようと思います(逃亡)。