TLSで接続している時にSNIを利用しているとログにはドメイン名しか残らない

TLSで接続しているとき,SNIを利用しているとログに接続に利用しているServer Nameが残らず,ドメイン名しか残らないという問題にハマりました.

あるアプリケーションでリモートのAPIを叩くときにTLSのエラーが発生しました.

networkError: FetchError: request to xxx

↑のような感じのログです.xxxにはリモートのドメイン名が入っています.リモートに接続を試みると問題なく接続できます. TLSの検証にも成功します.アプリケーション以外の,途中のproxyなどのログはありません.アプリケーションを何度実行しても再現します.

という状況で,考えても何もわからんとなったのでパケットキャプチャして見ることにしました.TLSの場合だと暗号化されていますが,TLSネゴシエーションのどの部分で失敗したか,がわかるとデバッグの助けになるかと思って,です.

すると,Client Helloで失敗しており,パケットを睨むとServer Nameが想定しているリモートのドメイン名と異なることがわかりました.

ログに出力されたドメイン名はあくまで接続先としてしか利用しておらず,TLS的には異なるServer Nameでネゴシエーションしようとしていたため,TLSネゴシエーションに失敗しTLSのエラーが出ていたのでした.

気がついてみるとまぁそういうこともあるよね…ぐらいの気分になるんですが,気がつく前まではなんで手元のcurlだと接続できるのにアプリケーションだとだめなんだよ,嘘だろぐらいの気持ちでした….

結局の所,アプリケーションが何をしているかはコードを読むか,アプリケーションの出力を観察しないとわからないよね,というのが教訓です.

さて,ところでESNIが採用されていたらこの問題には気がつけたでしょうか….

レスポンスタイムの分析

ボーッとしていたら1年が過ぎてしまいました。この記事は、はてなエンジニア Advent Calendar 2022の4日目です。

はてなでSREをやっているhappy_siroです。

僕の所属しているチームでは定期的に継続的なパフォーマンスの劣化を確認しています。具体的には、先月や、先々月と比べて今のレスポンスタイムがどう変化しているか、というようなことを確認しています。このとき、エンドポイント毎の変化を確認しようとすると、エンドポイント数が膨大でなかなか難しい…という課題がありました。

この課題を解決するためのアプローチの一つが レスポンスタイムの平均 - happy_siro's blog です。今回はまた違った方法で戦ってみたので、それについて書きます。

今回のアプローチ

前回は、統計的仮説検定を利用して見るべきエンドポイントを絞ろうとしていました。今回は、見るべきグラフを工夫すれば人間が全部確認できるのではないか、という仮設でアプローチします。

グラフの工夫

グラフを書くライブラリの選定

今回は Vega-Altair: Declarative Visualization in Python — Altair 4.2.0 documentation を利用しました。 言語をまたいで共通で利用できることを目指した Vega という visualization grammar の Python による実装です。Pythonによるデファクトは、Matplotlib — Visualization with Python なんですが、言語をまたいで可視化の知識が流用できるかもしれない…というところに惹かれて Vega-Altair を使用しました。

試行錯誤

工夫の前に、アクセス数があまりに少ないエンドポイントについては確認する必要がないので、アクセス数である程度足切りしました。

ここから、グラフを試行錯誤してきます。 月ごとのレスポンスタイムをエンドポイント毎にグラフにしています。データはすべてダミーです。またこれらの作業はJupyter Notebook| Home で行っています。

まずは、単純な折れ線グラフです。 グラフは、Vega-Altair: Declarative Visualization in Python — Altair 4.2.0 documentation で書いています。選定の理由は、後に書きます。

何がなんだかわかりませんね。

ちなみにですが、最初はこういったグラフを睨みながらパフォーマンスの劣化を確認していました。 誰が見てもわかりやすい、というグラフではないのでグラフを眺めるセンスが要求され、担当者ごとにパフォーマンス分析の品質に差が生まれてしまいました。またこのグラフを眺めて考えるのはめんどくさい…という問題もありました。

もう少し工夫します。

小さいですね…。これは横にすべてのエンドポイントを並べました。 上に比べればエンドポイントごとの変化はわかりやすくなっています。これでもまぁ良いんですが、もうちょっと工夫します。

レスポンスタイムをy軸にとりx軸に時間をとると、一つのグラフの中で線が多くするか、グラフの数を増やすか、のどちらかになってしまいます。 そこで、y軸にエンドポイント名を、x軸に時刻を、レスポンスタイムを色で表すことにします。

具体的なレスポンスタイムは完全にわからなくなりましたが、傾向はなんとなくわかります。 このデータはランダムなので意味は読み取れませんが、実際のデータでも傾向は読み取れ、継続的に遅くなっているエンドポイントを発見できました。

既存のツールを利用しなかったのはなぜ

ツールが整備されていなかった、かつ、今すぐパフォーマンスの分析をしたかったから、です。 仕事をしていると手持ちの道具でなんとか問題を解く必要があるケースはままあります。そういったときでも汎用的な可視化ライブラリ、分析ツールでデータがあればパフォーマンスを解析していくことができました。 これは今回の作業の学びの一つです。

まとめ

グラフを工夫し確認する必要のあるデータを絞ることで、たくさんあるデータでも人間が全部みれそう、ということがわかりました。 データさえあれば分析や可視化は汎用的なもので対応可能だ、ということもわかりました。

Vega という可視化手法

Vegaという可視化手法があります.ドキュメントは A Visualization Grammar | Vega です. JSONでどのように可視化したいかを宣言的に記述して,対応しているツールに食わせるとグラフが出てくる,というものっぽい.

この手の可視化って,当たり前だけど言語ごとに全くやり方が違って,ちょっと別の言語で分析を試したいみたいな時に,可視化どうすんだっけが悩みの種だった. 正直,言語の文法を覚えるよりも可視化ライブラリの使い方覚える方が私は大変で,ここが乗り換えのハードルだった.

でもVegaが出てきたことで,もしかしたら可視化はこの文法を覚えたらOKになるかなと期待している.

Terrafrom Moduleを書く時に知っておいた方が便利なこと

Terraform Moduleを作るときのTips

ドキュメントの自動生成

variables の description から自動でドキュメントを生成してくれます.

Null

リソースの引数を Null にすると,Terrafromは引数が省略されたように振る舞います. 1つは,引数に応じてあったりなかったりを切り替えたいケースで利用します

variable "acl" {
   type    = string
   default = null
}

みたいにして

resource "aws_s3_bucket_acl" "this" {
       .
       .
       .
   acl = var.acl
       .
       .
       .
}

とすると,aclを指定しない場合は,aclを省略できます.terrafromではif文などでリソースの引数を調整する方法は用意されていないのでこのような方法を利用する必要があります.

lookup 関数

moduleのコードを読んでいると頻出です.前述したNullと組み合わせてよく使います.

lookup(map, key, default)

mapを引数に取り,指定されたkeyに値がなければ,defaultを返します.

例えば,

bucket  = lookup(access_logs.value, "bucket", null)

みたいに書くと,access_logs.value に key がないと,null が返ります.つまり,map にどのようなキーがあるかによってある設定の有効無効が切り替えられます.


他なんかあったけかな.

基本的すぎて書いていないけど,forとfor_each,三項演算あたりは覚えておかないと辛いと思う.moduleのコードを読んでいると,countやfor_eachで条件に応じてリソースを作成するかしないかを分けたりするのも頻出です.

とりあえず,最近覚えて便利に感じたことを書いてみました.

FireLens が OOM で死んでしまう

ECS でログを管理するために,FireLens を利用しています.ちょっと前に,FireLens で複数行のログを連結して出力することがサポートされました. 僕も一つのエラーログが改行で複数行で分割されるのを避けるために,これを利用して設定を書いたんですが,うまく動きません.起動してしばらくするとFireLensを動かしているコンテナがOOMで死んでしまうんです….

何が起こったか

以下のような設定をしました.抜粋です.

[SERVICE]
    Parsers_File /fluent-bit/parsers/parsers.conf
    Parsers_File /fluent-bit/etc/parsers_multiline.conf

[FILTER]
    name                  multiline
    match                 *
    multiline.key_content log
    multiline.parser      multiline-regex

[FILTER]
    Name         parser
    Match        *
    Key_Name     log
    Parser       json
    Reserve_Data True

[FILTER]
    Name  rewrite_tag
    Match xxxxx
    Rule  xxxx

[FILTER]
    Name  rewrite_tag
    Match xxxxx
    Rule  xxxx

[OUTPUT]
    Name               cloudwatch_logs

こういった設定でFireLensを動かしていると,以下のようなエラーメッセージを出力しOOMでFireLensのコンテナがOOMで死にます.

[2022/02/25 15:40:27] [error] [input:emitter:emitter_for_multiline.0] error registering chunk with tag: xxxxx

どうやって解決したん?

仮説を立てる

エラーメッセージでググってみると,以下のGitHubのイシューがヒットします.

これは,multiline filter を複数利用すると,ログが無限ループしてしまうというものです.今回の件は,multiline filter を複数使っているわけではない,という以外はこのイシューにぴったりでした.なので,FILTERが複数ありそれぞれ * でMATCHさせている場合でも同じような問題が起こるのではと仮説を立てました.

検証環境を作る

これが原因である,という確証がそこまで高くないので(イシュー通りの設定をしているわけじゃないので)ECSに検証環境を用意し,今回のエラーを再現します.以下のブログを参考にしました.

ほぼこのまま環境を作り,ログを出力するプログラムだけ,今回,実際にエラーになったログを出力するように置き換えました. そうすると,エラーが再現しました.

設定を作る

ここはもう単純に FILTER の Match と Rule を工夫して必要なログが必要なフィルタしか通らないように書き換えただけです. そうすると,エラーが出なくなりました.

まとめ

結論は

FILTERが複数ありそれぞれ * でMATCHさせている場合でも同じような問題が起こるのでは

という仮説が正しかったということです.

結論だけ見ると,検証環境を作るコストが大きく見えてしまいます.しかしそうではなくて,今回はたまたまエラーが再現でき,問題を回避する設定がうまくいっただけです. エラーを再現できなかったり,想定していた設定ではうまくいかなかった可能性は十分あります.まぁ,設定も決して一発でかけたわけじゃなくて,予想外のハマりどころはありましたし….

ということで,問題解決の王道である仮説を立てて検証をして…というやつはやっぱり効きますよ,という話でした.

Amazon RDSのディスク容量は400GBを超えたサイズで作ると良い

Amazon RDSのディスク容量は400GBを超えたサイズで作ると良いです。500GBとか。 理由は、こうしないとディスク容量をスケールさせる時にレガシーメソッドが使われてしまい、パフォーマンスが劣化するから。 このせいで、EBS Byte Balance が使い切られてベースラインパフォーマンスに制限されました。また、この挙動は400GBを下回る容量から、超える容量にスケールするときは必ず発生するみたいです。

もちろんこの辺りの挙動は Amazon RDS のパフォーマンスまたはダウンタイムに影響する要因 のようにドキュメントに書かれてます。ちゃんとドキュメントは読みましょうね…。

ただまぁ

400 GB (Oracle データベースインスタンスの場合は 200 GB) を超えてスケーリングする場合、Amazon RDS はスケーリングにレガシーメソッドも使用します。レガシーメソッドの使用中は、パフォーマンスが低下することがあります。

というような書き方なので、チャレンジしてみてサポートに問い合わせるハメになったんだろうなぁという気はしていますが…。