mackerel-plugin-axslogを使ってみた

Mackerelでアクセスログを集計したいときに、普段は公式プラグインであるmackerel-plugin-accesslogを使っていた。

そんな中ふと下のエントリーを思い出し、高速であるという点も気になるし、いくつかオプションも異なるということで試しに使ってみることにした。

kazeburo.hatenablog.com

mkr plugin installをすることでインストールできる。*1

mkr plugin install --upgrade kazeburo/mackerel-plugin-axslog@v0.2.1

インストールされたのを見たら、あとは必要なオプションをいくつか入れることですぐ使い始められる。

(mackerel-plugin-accesslogとオプション名が結構異なっているので注意)

[plugin.metrics.axslog]
command = '/opt/mackerel-agent/plugins/bin/mackerel-plugin-axslog --key-prefix=all --format=ltsv --status-key=status --ptime-key=reqtime --logfile=/var/log/nginx/access_log'

これだけで準備完了であとは待っていたらmackerel-plugin-accesslogに似たようなメトリックが表示されるようになる。

アクセス数の数字について

実際にアクセスしてメトリックを確認したところ、このようにアクセス数の数字が小数点以下の数字になった。

f:id:cohalz:20200628002338p:plain

当然1分間に0.0833回アクセスしたわけではないので、どういう実装になっているか見てみたところこのようになっていた。

fmt.Printf("axslog.access_num_%s.2xx_count\t%f\t%d\n", keyPrefix, s.c2xx/s.duration, now)

https://github.com/kazeburo/mackerel-plugin-axslog/blob/v0.2.1/axslog/axslog.go#L200-L206

カウント(s.c2xx)を期間(s.duration)で割っているということがわかる。

計測された数を期間で割っているのでつまりは「平均して1秒あたりにどのくらいのリクエストが来たか」というメトリックになっているということがわかった。 *2

何故こうなっているのか不思議だったけど、おそらく「プラグインの実行が何らかの形で失敗した場合、集計されるべきだった分が次回に加算されてしまい数字が大きく出てしまう」ということを回避するための仕組みなんだろうと思った。*3

一度プラグインの実行に失敗して次回1分後の集計の範囲が倍になったとしても、カウント数も期間も等しく倍になっているためメトリックとしては大きく変わることはないということになる。

このようにメトリック投稿を復帰させたあとのグラフに悪影響を及ぼさない上にメトリック自体も集計タイミングに依存しない、という感じでわかってしまえばなかなか合理的なメトリックになっているということがわかった。

filterについて

Usageにある通り、mackerel-plugin-axslogにはfilterオプションが存在する。

--filter= text for filtering log

このfilterの使い方についても調べてみた。

使い方

コードを見たところ、JSON/LTSVの文字列をパースする直前にbytes.Indexでマッチしているのか見ているようだった。

if len(filter) > 0 {
    if bytes.Index(b, filter) < 0 {
        continue
    }
}
c, pt, st := r.Parse(b)

https://github.com/kazeburo/mackerel-plugin-axslog/blob/v0.2.1/main.go#L50-L55

パースした結果を見るわけではないので、例えばLTSV形式のログでフィルタを使いたい場合は --filter="method:POST" のようにkey:valueの形式で指定するという使い方になる。

使い所

そしてこのフィルタ機能がmackerel-plugin-axslogを選ぶ大きな利点になっていると個人的に思っている。

というのもmackerel-plugin-accesslogではログからすべてのレイテンシとステータスコードを集計するため、ログに傾向の違うリクエストが混ざっている場合に実感とは異なるメトリックの傾向になるということがよくあった。(99パーセンタイル値だけが高い値を示しているなど)

そういう場合に、このフィルタ機能を使うことで重要なエンドポイントに絞ったレイテンシやステータスコードの集計ができるようになりそう。

そしてプラグインは複数実行できるので、confにフィルタを別にしたプラグインを複数書くことでフィルタしたメトリックをいくつも出すことができる。

ただし、並列で何回も同じアクセスログを読み直すので効率は悪く負荷が増え、メトリック数もその分増えるのでその点は考慮して工夫する必要がある。

例えば、本当に重要な条件のみに絞ったり、ログの形式をフィルタに合わせた形に変たりなどして複数実行の数を減らすとか、無理が出たらmackerel-plugin-axslogじゃなくてちゃんとログ集計基盤を作るとかになるとは思う。

とはいえアクセスログから1つ2つ重要な部分のみに絞った集計を少ない手間で可視化できるというのは相当に便利だとは思う。

まとめ

mackerel-plugin-axslogは後発のプラグインということもあり、フィルタのようなmackerel-plugin-accesslogにはない機能もある、ということでかなり面白いプラグインということがわかった。

*1:mkr plugin installでプラグインをインストールする - Mackerel ヘルプ

*2:試しに期間を正確に1分と仮定すると0.0833 * 60 = 4.998となり確かにほぼ整数に近い値になった。

*3:fluent-plugin-mackerelを使ってMackerelにメトリックを投稿する際にも、途中のログ配送が詰まると復旧後に加算されてしまうという現象が起こる。

Varnishでレスポンスをカスタマイズする方法

表題の方法を実現したくなって、調べたところ実現する方法が結構面白かったのでメモ。

例えば以下のような「キャッシュ破棄リクエストを受け付けて200を返す」というVCLがあったとする。

sub vcl_recv {
    if (req.method == "BAN") {
        ban("req.http.host == " + req.http.host + " && req.url == " + req.url);

        return(synth(200, "Ban added"));
    }
}

この状態で curl -XBAN localhost:6081 を実行してみると、レスポンスは以下のように Ban added だけではなく他のHTMLタグや諸々が含まれて返ってくる。

<!DOCTYPE html>
<html>
  <head>
    <title>200 Ban added</title>
  </head>
  <body>
    <h1>Error 200 Ban added</h1>
    <p>Ban added</p>
    <h3>Guru Meditation:</h3>
    <p>XID: 196749</p>
    <hr>
    <p>Varnish cache server</p>
  </body>
</html>

そしてこのレスポンスをもし Ban added だけにしたい場合にどのようにするとよいかという話。

結論としては、この状態から以下のように vcl_synth を変更することで実現できる。

sub vcl_synth {
    if (req.method == "BAN") {

        synthetic(resp.reason);

        # これも上と同等の処理
        # set resp.body = resp.reason;

        return (deliver);
    }
}

結構不思議な感じだけど、これで何故動くのかを説明していく。

まず synthetic 関数について、公式ドキュメントには以下のように説明されており、レスポンスをセットする関数になっている。

synthetic(STRING) Prepare a synthetic response body containing the STRING. Available in vcl_synth and vcl_backend_error. Identical to set resp.body / set beresp.body.

https://varnish-cache.org/docs/6.0/reference/vcl.html#synthetic-string

そして resp.reason について。

return synthした際の2つの引数は resp.status , resp.reason にそれぞれセットされる。*1

今回はそのうちの resp.reason を使って参照し、レスポンスを Ban added だけに書き換えることができたという理由になる。

ちなみに注意事項として、synthetic を呼ぶ際は vcl_recv でreturnしたときと同じ条件で囲わないとBANメソッド以外の場合にもレスポンスが書き換わってしまうというのがあるため、もし元々のHTMLも返したい場合には気をつける必要がある。

これを応用してこのような固定のレスポンスを返すだけではなく、例えばリクエストの User-Agent をレスポンスとして返すみたいなことも以下のようにして実現できる。

return(synth(200, req.http.User-Agent));

もちろんVarnishはキャッシュサーバなので複雑なレスポンスを組み立てて返すというのは向いていないけれど、例えばキャッシュ破棄のようなロジックを入れる際にレスポンスを少しカスタマイズする事はあると思う。

例えばvmod_xkey*2を使ってタグベースのキャッシュを行った際に、キャッシュ破棄できた数を返すことで「複数のVarnishサーバで合計でどのくらいキャッシュ破棄できたのか」の集計がしやすくなるなどがありそう。

同じ場所に旅行をする、ということ

何かの用事で過去に行ったことがある場所にまた旅行しに行く、というのをよくやっている。

特に学生時代の修学旅行や留学、家族旅行で行った場所を行くようにしている。

同じ場所に旅行をするモチベーション

いい場所だったからまた行きたい、というのもあるけれど、個人的には下の3つの理由で行くことが多い。

  • 当時は行けなかったところにリベンジできる
  • 当時と変わっているところ・変わっていないところなど時間の経過を感じられることがある
  • 思わぬ再会があったりする

同じ場所に旅行をするようになったきっかけ

そもそも大学入った頃にお金がないというのもあり、旅行に行くという習慣がなかった。

夏休みでどこか行ってみようと思ったものの、どこに行こうか良いのが思いつかなかった。

そこで小さい頃によく行っていた・実家から日帰りで帰れるというお手頃な点から、養老天命反転地に行ったのが初めてだったと思う。

www.yoro-park.com

ここから、過去に行ったところにまた行くのは面白いんじゃないかと思うようになり、奈良や広島など修学旅行で行ったところにまた行くということをするようになった。

それから色んな場所に行く機会があり、最後に行ってから時間の経った場所というのも増えてきた。

時間の経過を感じる: 石巻の例

2015年6月に初めて石巻に行き、街の復興の様子を見るということがあった。

「今どうなってるかな」と気になって、2017年3月にまた行くことができた。

当時と変わらない風景もあれば、復興が進んで知らない風景もあり、2015年には知らなかった海鮮のお店も知ることができた。

この店は行った当時は仮店舗だったが、去年に震災前の場所に店を開くことができたらしく、また風景が変わっているので楽しみになっている。

www.tomofukumaru.co.jp

思わぬ再開: 台湾の例

2019年の10月に台湾(桃園)に行った。

過去に2016年に短期留学をしていたが、その場所が近かったというのもあり当時住んでいたあたりを歩き回るなどしていた。

そしてそこには当時交流のあったIngressプレイヤーがまだおり、自分の名前を見てすぐにゲーム内のチャットで話しかけてもらった。

3年も経って名前を覚えてもらっていたのも嬉しいし、まさか再開できるとも思っていなかったので本当にまた行けてよかったなと思った瞬間だった。

終わり

新しい場所に行くというのも面白いけれど、長らく行ってない場所にまた旅行をするというのもどうでしょうか。

__twitter_impression=true というクエリ文字列を含むリクエストは204を返すのが望ましい

__twitter_impression=true というクエリ文字列を見かけて、これはどういうものか調べたメモ。

これは名前の通りにTwitterが付与しているクエリ文字列で、Publish faster articles with AMPには以下のように書かれている。

When users are presented with the optimized AMP version of your page, Twitter instructs the AMP runtime to also ping your original article URL. This allows your analytics software to record a visit as if the original article were viewed.

For these ping requests, Twitter appends an additional query parameter to your URL — __twitter_impression=true — which you can use to distinguish these AMP views from organic traffic. (For example, to understand the impact of AMP on your audience, or filter these impressions if you already instrument AMP elsewhere.)

要約すると、以下のことが書いてある。

  • TwitterからAMP版ページに遷移する際、AMP版のページを表示するとともに非AMP版のページにもリクエストを飛ばす(pingと呼んでいる)
    • (pingと呼んでいるものの、アクセスログを見たところ普通に GET リクエストであることがわかった)
  • そのpingリクエストには区別のため、 _twitter_impression=true というパラメータが付く

そしてこのクエリ文字列の扱いに関しても書いてある。

When receiving a request for an article including the __twitter_impression=true parameter, you should return an HTTP 204 response, with no response body. While a regular HTTP 200 response is valid, it is wasteful. You can improve performance and save your and your user's bandwidth by omitting it, the response body will be ignored by Twitter and the AMP runtime.

そのパラメータが付いたリクエストに関しては中身を見ないので、単に204を返すことによりパフォーマンスの向上(レスポンスの高速化?)やユーザの帯域を節約できるということらしい。

nginxであれば、以下のように $arg_name *1を使うことで実現できる。アンダースコアが3つ並んでいるのは変に見えるけどちゃんと動く。

if ($arg___twitter_impression = "true") {
    return 204;
}

2019年

仕事

この一年で、普段の運用に関する話題(AWSやらミドルウェアやら)はかなりわかるようになった。

一般的な話題について来れるようになっただけではなく、自分がかなり詳しいと言える部分も出始めてきたのは嬉しい。

イベントに関しても1月にはHatena Engineer Seminar、7月にはAWSのイベントで登壇することもあったりと結構チャンスには恵まれた一年だったと思う。

既にとあるところで来年登壇一つする機会を貰えたので、今までよりももっと踏み込んだ話をできればと思う。

生活

京都に引っ越したのは2018年なので、今年はまるまる京都にいたことになる。基本困ることはなくて歩いていればだいたい目的地にはつくし、住んでいる場所も安く快適ではある。

とはいえ部屋は二年更新なので別の部屋にすることも可能になってくるのでどうするか考えることになりそう。

あと最近はだんだん寝るのが遅くなってきているのでなんとかしたい。

趣味

Ingressのイベントで遠くに行ったのは韓国と台湾、国内だと沖縄が遠くてそれ以外は結構近場に行った印象。

Ingress関係なく行った場所だと、有馬温泉が良くてかなり行きやすいことにも気づいたので良かった。

来年はもう少し突発にでも色んな所に行けると良いかな〜と思っている。例えば九州とか。

ポケモンも買ってXY振りに対戦に復帰してかなりやっている。大学時代の友人と6年振りに対戦したのはかなり嬉しい出来事だった。

別途ブログを開設したのでそこもどんどん動かしたいな〜とは思っている。

インターネット・感情

Twitterをすることがほとんどなくなってしまった。あまり良い話題が流れてこないというのもあるし、特に他人に興味がないという気持ちがだんだん強まっていって見るのをやめてしまった。

とはいえインターネットで生きる上で幽霊のようになるのは避けたいし、来年はうまい落とし所を見つけないといけない。

総括

まぁまぁ仕事にはちゃんと向き合って成長できたかなとは思うけど、他の部分を犠牲にしていたという部分があったのでバランス取ってやっていけたらと思う。

あんまり浮上はしていないけれど、誘われたら色々やっていきたいので来年もよろしくおねがいします。

Envoy に入門した話

この記事は、はてなエンジニア Advent Calendar 2019の11日目の記事です。

前置き

Envoyは今話題のIstioやApp Meshのコアに使われているなどサービスメッシュの文脈で名前が出ることが多いですが、Envoy自身はnginxはHAProxyのようなプロキシ・ロードバランサの一種なのでサービスメッシュ関係なく案外簡単に導入することができます。

そのEnvoyを利用する機会があったので、概念の整理とともにどうやって設定を書いていけば良いかまとめていきます。

ファイル分割

設定項目が多いのですぐに行数が増えていくのでファイル分割は最初から考えておくと良いです。

外部通信して設定更新するという仕組み(discovery service)があり、その仕組みの中でファイルから読み込む方法が取れるという世界観です。

機能ごとにCluster, Listener, Routerなどといった名前がついていてそれぞれが何を設定できるのか違ってます。

そしてそのClusterやRouterといった機能ごとの単位でしか分割できないので、さらに細かく区切るということはできません。

ファイル名の指定する場所も機能ごとに変わっていて、リスナとクラスタ設定であればdynamic_resourcesという部分で指定し、ルーティングの設定はリスナの中で指定します。

ファイル読み込みに関しては以下の記事が詳しいです。

www.katacoda.com

medium.com

フィルタ

リクエストを受け取ってなにか処理するものをフィルタと呼びます。

ルーティングするものはenvoy.router, Fault Injectionするものは envoy.fault というフィルタを使います。

フィルタは上に書いた順に処理されるので、ルーティングをするenvoy.routerは最後に書くのが普通です。

今紹介したフィルタはHTTPフィルタ*1 の一種で、他にはTCPフィルタやRedisフィルタなどもあります。

ログ

ログはリスナ設定のとこに書きます。*2

JSONでログを出す場合にはjson_formatというやつが使える...のですが、こちらはすべてクォートで囲まれて文字列になってしまい数値やboolなどを出せません。

なのでクォートで囲まれたくない場合は format で頑張ってJSONの形式を組み立てる必要があります。

まだ検証できていないけれどv1.12.2からあるtyped_json_format *3を使えば数値うまく出せるのかも知れません。

ちなみにログには必ずRESPONSE_FLAGSというものを出したほうが良いです。(デフォルトでも含まれています)

これはステータスコードの細かい理由が記録されるもので、サーキットブレーカー由来なのかそもそも接続に失敗したのかなどが書いてあります。

Envoyの設定チューニングする場合も、このフラグがどういう割合で出ているのか見ることが多いです。

設定ファイルの書式を確認する

ファイル分割をしていると起動->ファイル読み込みという順になり、設定に不備があってもその設定が読み込まれないだけで続行されるという感じになります。

またログもerrorではなくwarningなので知らないと気が付きにくいです。

なのでCI等で設定の検証を回したいなどの場合は、こういう感じで実際に数秒起動してみてwarningのログが出るかを見てチェックするのが良いです。

OUTPUT_FILE=/tmp/envoy.log
CONTAINER_ID=$(docker run -d -p 10000:10000 envoyproxy/envoy:latest envoy \
   --config-path /etc/envoy/envoy.yaml --service-node node \
   --service-cluster cluster --component-log-level \
   config:warning,upstream:error,main:error,runtime:error)
echo $CONTAINER_ID
sleep 5
docker logs $CONTAINER_ID 2> $OUTPUT_FILE
docker kill $CONTAINER_ID
if [ -s $OUTPUT_FILE ]; then
  cat $OUTPUT_FILE
  exit 1
fi

リトライ・タイムアウト

何回リトライするかとか、何秒でタイムアウトするとかを設定できます。

タイムアウトに関する設定はかなり多く最初は混乱しますが、基本的には timeoutper_try_timeout をよく考えるで良いです。

  • timeout:リトライも含む全体のタイムアウト
  • per_try_timeout: 1回のリクエストのタイムアウト
  • num_retries: リトライを何回するか

どういう場合にリトライするかも決められます。*4

5xx が他のルールを含んでいることもあり大体はカバーできているはずですが、POSTリクエストもある場合はretriable-4xxも入れておくとよいのかもしれません。

リトライのバックオフ間隔も変えることができますが*5、デフォルトで既に設定されているのであまり変えることはないかも知れません。

adminインタフェース

別のポートを指定して管理画面を起動することができます。

今動いている設定や統計情報がわかるのでメトリックを取りたい場合はこちらも立てておく必要があります。

多くの情報が確認できる上にこの管理画面からプロセスを落とすこともできるので間違って全世界に公開しないように気をつける必要があるのだけ注意です。

サーキットブレーカー

同時リクエスト数や同時リトライ数など設定できます*6

この中で一番有用なのはmax_retriesで、今このタイミングでリトライしている同時リクエスト数が一定値を超えている場合はそれ以上通信しません。

これにより特に難しいことしなくても詰まっている場合にだけ通信を減らすことができ影響を小さくすることができます。

そしてリトライが捌けたらまた通常通りリクエストを通すようになるという挙動です。

同時リトライ回数の他にもありますが総リクエスト数に影響されるものなので具体的に良い数字を決めるのは難しいと思います。

Fault Injection

Envoyが条件によって通信を遅延させたり、特定のステータスコードを返せる機能です。

これにより通信に時間がかかった際の表示や特定のステータスコードが返ってきた際の挙動を確認することができるので開発時にとても便利です。

確率や特定のヘッダを条件にできるので、ユーザから使われないヘッダで応答を変える条件を書いておいて、いつでも確認できる状態にしておくと良いと思います。

Keep-Alive を無効にする

毎回コネクションを切りたいときにどうすればよいかについて、前に記事を書きました。

通信先がHTTP/1.1だとわかっているなら最初から設定しておくと後ではまらなくていいと思います。

core.cohalz.co

終わりに

Envoyは設定項目が多くまだまだ知らないことがたくさんあります。

パフォーマンスチューニングなんかも全然できていないのでそこら辺も調べていきたいですね。

という記事を書いていたら Envoy Meetup Tokyo #1 というイベントを来年やるようでした。

envoytokyo.connpass.com

気づいたときには満員でLT枠も埋まっていたので行けるかどうかわからないですが...という話題でした

明日のはてなエンジニア Advent Calendar 2019担当は id:motemen です。

リンク集

  • Envoyをロードバランサとして利用する際にどう設定するか日本語で解説してくれている記事

i-beam.org

  • Envoyでユースケース別に設定を学べる
    • nginxやHAProxyとの構文比較もあり英語だけどかなり理解しやすいと思います。

www.katacoda.com