IX2107でUTMを有効にしたところ、公開しているRedmineがタイムアウトするようになりました。
Nginxのリバースプロキシを挟んでいて、同じところでほかのWebサービスも動かしています。TCP接続はできるのに、その先が進まない感じです。
UTMの設定を入れた直後だったので、まずはこの辺が怪しそう。キューを見たり、両端でパケットを採ったりしながら、どこまで検査対象を絞れるか調べてみました。
今回はLAN内からインターネットへの通信のみを検査出来ればよいので、最終的には、プロキシの公開TCP443だけを検査除外する形でひとまず落ち着いています。
⚠ 注意事項
設定内容やプログラムの内容は、用途・環境に応じて適切なものが変わります。
各種設定値や環境情報についてよく理解を深め、壊れてもよい環境で十分に検証してください。
なるべく正確に書くよう心掛けていますが、本投稿内容を実施される際には自己責任の下でお願いいたします。
構成と症状
回線はサーバー公開用のPPPoEと、通常利用用のIPoE（MAP-E）の2系統を同じIXで両方を終端しています。
公開HTTPSはPPPoEからサービスNAPTでDMZのプロキシへ転送する構成で、拠点間VPNも張っています。
ざっくりこんな感じです。
外部クライアント → PPPoE公開HTTPS → IXのNAPT／UTM → DMZリバースプロキシ → 各種Webアプリ
通常のインターネット通信 → PPPoEまたはMAP-E
拠点間通信 → VPNトンネル
対象の通信をUTMから外すと、DMZに置いてあるリバースプロキシ配下のRedmineはすぐ返ってきます。戻すとまたタイムアウト。
ブラウザの「速くなった気がする」だけだと微妙なので、curlでも接続時間、TLS確立時間、HTTP応答までの時間を見ておきました。
キューは詰まっている。でもCPUは暇そう
show utm status
見てみると、GE0のキューが1,400まで溜まり、overflowも増え続けていました。
ただ、CPUは約16〜18%、メモリも約21%。UFSやNAPTが上限に達している様子もなく、回線を使い切って輻輳しているわけでもなさそうです。
単純に性能が足りないのかなと思ったものの、この数字だけだとどうも判断しづらい。
CPUが低いからUTMも余裕、とは限らないので、条件を変えながらキューを追ってみることにしました。
見るのはcurrentとoverflowの増え方。peakは過去の最大値なので、そこが1,400のままなのはそれはそうだなということで放置。
なお、GE0はPPPoE専用の表示ではなく、同じ物理経路を使うMAP-E側も含めて見ている点が今回の特記事項です。
まずは、UTMでの検査機能を一つずつ外してみたが……
IPS、アンチウイルス、URLフィルタリング、Webガードをそれぞれ外して比較してみました。
どれか一つを外せば直るかと思ったのですが、そう簡単でもなく、単独で外しても解消しませんでした。
ということで、特定の機能やシグネチャが原因とは言い切れ状況に。
もうちょい詳しく確認したいので、HTTPSやTCPを扱う共通部分も含めて、もう少し見てみることにしました。
両端でパケットを採ってみる
次は、外部クライアントとDMZのプロキシで同時にキャプチャ。
TLS 1.2ではクライアントが送った鍵交換以降のデータが、プロキシ側に見当たらない接続がありました。
TLS 1.3でもFinishedや暗号化された要求が片側にしか出ずに、バージョンを変えれば済む話でもなさそうです。
別の接続では、要求が遅れて届いてNginxに302の記録が残っているのに、クライアントではHTTP応答を受け取れませんでした。
純粋にACKがプロキシ側に見えず、サーバーが再送を続けている場面もあります。
クライアントが送ったものが途中で届かなくなるところまでは見えました。
とはいえ、IXのWAN側とDMZ側をミラーで同時に採れたわけではないので、IX内部のどこで止まったかまでは結論が出せず。
UTM機能での検査除外の通信を公開HTTPSだけに絞りたい
いったんMAP-E側の検査はそのままで、PPPoE側だけUTM検査を止めると、キューが減ってRedmineも復活。再び検査すると症状が戻りました。
このままPPPoE全部を検査対象から外すのも範囲が広いので、ネットワーク、ホスト、ポートの順に狭めてみました。
| 試験条件 | 観測結果 |
|---|---|
| DMZ全体を除外、他LANの検査は継続 | キューが0へ減少、Redmine回復 |
| 他LANを除外、DMZの検査は継続 | キューが1,400に達し、タイムアウト |
| 公開プロキシだけを除外 | キュー飽和なし、Redmine回復 |
| 公開プロキシを検査し、他のDMZホストを除外 | キュー飽和とタイムアウトを再現 |
| 公開プロキシのサーバー側TCP443だけ除外 | 約40秒間キュー0、3回とも約0.03秒で応答 |
| 同ホストのその他通信を除外、サーバー側TCP443は検査 | 約60秒でキュー0→1,063→1,400、3回ともタイムアウト |
公開TCP443を検査に戻すと、キューとoverflowがまた増えました。かなりボトネックになっている箇所が絞れてきた感じです。
ただし、このとき「その他通信」の除外は0ヒットでした。
そちらを十分流した比較ではないので、ほかの通信なら絶対に大丈夫、とまでは言えないなと。
公開TCP443だけ外して、ひとまず運用
ということで、PPPoE全体の検査を戻し、プロキシのサーバー側TCP443だけを双方向で除外することにしました。
プロキシ自身が外へHTTPS接続する通信や、ほかのポートまで丸ごと外す設定にはしていません。
もともとの除外ルールは残しています。
ここはIPとポートでの除外なので、Redmineだけでなく、同じプロキシのTCP443で公開しているほかのサイトも対象になってしまいますが致し方なし。
もともとUTMで見たいのは、メインとしては内側の端末から外へ出ていく通信なので、今回は公開HTTPS側を外すことにしました。
公開側の検査は受けなくなりますが、内側から外への通信とVPN内の検査は残す、という割り切りです。
変更後は約5分、30秒おきに11回確認。キューは最大193、最後は8で、overflowは増えませんでした。
Redmineも11回とも302が返り、約0.026〜0.129秒。Redmineのログイン画面も200になりました。
その後、VPN内の通信にも検査をかけた状態で短時間確認し、キュー0とRedmineの応答を見てからwrite memoryしています。
今回確認したのはログイン画面までで、認証後の操作や全拠点の業務通信、長時間の負荷試験まではやってないのですがとりあえずは様子見。
syslogに履歴が来ない件も直す
ついでに、syslogに検査履歴が出てこないのも気になったので確認。
UTMのログレベルがnoticeだったため、通常のURL判定が出ていませんでした。infoに変えて、各検査機能のログも有効にしておきます。
logging subsystem utm info utm security-log
これで装置内にUTM.007のURL判定（Pass）が出て、syslogのinfo送信数も増えました。
なお、infoでも全通信の履歴が出るわけではありません。
今回除外した公開HTTPSも検査しないので、その検査履歴は残りません。
今回入れた除外設定
使った設定はこんな感じです。実アドレスとACL名は伏せてあるので、<PROXY_DMZ_IP>はプロキシのDMZ側IP、<UTM_IGNORE_ACL>は既存のUTM除外ACL名に読み替えてください。
! 既存の除外エントリーを残したまま、公開HTTPSの2条件を追加 ip access-list <UTM_IGNORE_ACL> option nocache ip access-list <UTM_IGNORE_ACL> permit tcp src <PROXY_DMZ_IP>/32 sport eq 443 dest any dport any ip access-list <UTM_IGNORE_ACL> permit tcp src any sport any dest <PROXY_DMZ_IP>/32 dport eq 443 ! 既存の全機能除外ACLを使用し、PPPoEとMAP-Eの検査を有効にする utm ignore ip access-list <UTM_IGNORE_ACL> utm enable utm interface GigaEthernet0.1 utm interface Tunnel0.0
この環境ではGigaEthernet0.1がPPPoE、Tunnel0.0がMAP-Eです。VPNトンネル側の検査設定も残しています。
既存ACLへの追加なので、ほかの除外エントリーや機能別の例外を消さないようにします。
TCPの2行は、プロキシの送信元443と宛先443をそれぞれ指定しています。IXのホワイトリストは逆方向にも評価されますが、今回は念の為、双方向で2行で設定しました。
NAPTやパケットフィルタは特に変更していません。
DMZ側のIPでACLにヒットしたのはこの環境での結果なので、別の構成で使う場合は変換位置とACLのヒットを見ておくと良いかと。
おまけ：キューの変化を並べてみる
show utm statusの出力
実際の出力も残しておきます。show utm statusのうち、比較したGE0の部分だけ抜粋しました。
公開HTTPSを検査したとき：約60秒後
UTM Queue Status:
GigaEthernet0 buffer:
1400/1400 (curr/peak), 2840991/1140757 (queued/overflow)
公開HTTPSだけ除外したあと：約5分後
UTM Queue Status:
GigaEthernet0 buffer:
8/1400 (curr/peak), 2858125/1141274 (queued/overflow)
8/1400は「今は8、過去最大は1,400」。ここで右側だけ見て、まだ詰まっていると勘違いしないようにしたいところです。queued/overflowの右側はoverflowの累計です。
overflowは累計なので、別々の試験の数字をそのまま引くと間の試験まで入ってしまいます。
検査ありの試験内では1,139,274→1,140,757で1,483増加。除外後の5分間は1,141,274のままで増加0でした。グラフも、それぞれの試験開始時からの増分にしています。
2つの試験を、開始からの経過時間で重ねたグラフです。連続した一回の記録ではありません。約30秒おきに見ているので、測定の間の動きまでは追えていません。
公開HTTPSを検査対象に残した再現試験
公開TCP443を検査に残し、プロキシのその他通信を除外したときの記録です（その他通信の除外は0ヒット）。
| 開始からの経過 | キューcurrent | overflow増分 | Redmine |
|---|---|---|---|
| 0秒 | 0 | 0 | HTTP応答待ちでタイムアウト |
| 約30秒 | 1,063 | 0 | HTTP応答待ちでタイムアウト |
| 約60秒 | 1,400 | 1,483 | 接続タイムアウト |
最初はキュー0を確認した直後の要求でもタイムアウトしました。ただ、要求している間ずっと0だったかは分からないので、この一回だけでキューと無関係とも言えません。
公開HTTPSだけを除外した適用後の5分監視
| 開始からの経過 | キューcurrent | overflow増分 |
|---|---|---|
| 0秒 | 0 | 0 |
| 約30秒 | 148 | 0 |
| 約60秒 | 193 | 0 |
| 約90秒 | 11 | 0 |
| 約120秒 | 8 | 0 |
| 約150秒 | 2 | 0 |
| 約180秒 | 2 | 0 |
| 約210秒 | 2 | 0 |
| 約240秒 | 0 | 0 |
| 約270秒 | 0 | 0 |
| 約300秒 | 8 | 0 |
除外後も一時は193まで増えましたが、その後は減ってoverflowも増えず。Redmineも11回とも応答しました。
この5分間はVPN内の検査を追加する前の記録で、VPN追加後は別途短時間の確認です。
ひとまず、この設定で様子見
原因まできれいに分かったわけではありませんが、公開HTTPSに検査をかけると再現し、そこだけ外すと使えるところまでは絞れました。
本来見たかった内側から外への通信は検査を残せたので、ひとまずこの設定で様子を見ることにします。
IPやドメイン、認証情報などは省略しています。上の設定は今回の環境での暫定対応なので、そのまま別の環境へ持っていけるものではない点だけご注意を。