この記事は東京工業大学デジタル創作同好会traP アドベントカレンダー2019の25日目の記事です。

とーふとふです。
traPのブログで記事を書くのは久しぶりな気がします。

現在私はSysAd班という、WikiやtraQ(部内製チャットサービス)など部内向けのサービスの開発・運用を行っているチームのリーダーをしています。
今回のアドベントカレンダーではSysAd班の活動の中から、個人的に面白いなと思った障害とその原因究明、対応について書きたいと思います。

前提 traQとShowcaseについて

今回の障害で関わる2つのtraP SysAd班製サービスであるtraQとShowcaseについて簡単に説明します。

traQ

traPの部内向けチャットサービスです。
300人以上いるメンバーがtimesなどの雑談含め様々なやり取りをすると、大体週に9000メッセージほどが投稿されます。
こういったコミュニティーの場合Slackを使うことが多いと思うのですが、そうするとSlackの無料枠の関係上2週間前のやり取りを参照できなくなってしまうため自分たちで開発し運用しています。
PWAによるオフライン対応はもちろん、WebhookやBot機能・音声通話などの機能があったり、TeXを利用したりもできます。
リポジトリはいくつかありますが主なものはtraPtitech/traQ、traPtitech/traQ_R-UIで開発を進めています。

サークル内チャットサービスに音声通話を実装しました！
活用されてほしい pic.twitter.com/RFqDdPVQDK

— すぱすぱ (@__spaspa__) September 1, 2019

traQ、理系大学っぽく数式表示に対応した pic.twitter.com/ClaU97OGHg

— すぱすぱ (@__spaspa__) November 6, 2019

また、ログイン時にJWTを各ドメインに発行することで、traP内で運用している他サービスに対してSSOを実現しています。

Showcase

traP部内向けPaaS基盤です。
昨年までtraPに在籍していた@kazが開発しました。

部内で運用しているGiteaのリポジトリのルートにshowcase.yamlというファイルを置くだけで、自動的にShowcase上にアプリケーションがデプロイされ、<リポジトリ名>.<ユーザー名>.trap.showというドメインでアクセスができるようになります。

Netlifyのようにビルドのみを行った上での静的サイトの配信や、MariaDBやMongoDBを使った動的なアプリケーションのデプロイも可能になっています。
FlythmやTyping WarなどのtraPが外部に公開しているゲームの基盤としても使われています。

サーバー内部の構成は以下のようになっており、Showcaseコンソールはshowcase.trapti.techでホストされており、traQで発行されたJWTで認証を行っています。

認証が行えなかった場合は、traQにリダイレクトしトークンを発行したあとShowcaseコンソールに戻ってくる仕組みになっています。

Showcaseでの実際のコードは以下のようになっていました。

const ensureAuthorized = async (ctx, next) => {
	try {
		const token = ctx.cookies.get("traP_token");
		if(!token){
			throw new Error("No token");
		}

		const verify = Promise.promisify(jwt.verify);
		const verified = await verify(token, pubKey, {algorithms: "RS256"});
        // 中略
	} catch(e) {
		console.trace(e);
		ctx.redirect(`https://q.trap.jp/login?redirect=${encodeURIComponent(ctx.request.href)}`);
		return;
	}
	await next();
};

少し古い資料ですが、開発者の@kazによる発表資料もご覧ください
Showcase

障害の発生とその対応

上で紹介したShowcaseとtraQの間で認証のための無限リダイレクトが発生し、traQが停止するという障害が10月28日に発生しました。
ここではtraQのメッセージを引用する形で、実際の障害から対応までの流れを載せます。

19:30 障害確認

TwitterでメンバーからtraQが利用できないという報告を受けました。
実際に各種サービスを監視しているPrometheusを見てみると、19時15分ごろからtraQがデプロイされているs512サーバーのSwapが急激に増大し、CPUが100%に張り付いていることが確認されました。

19:42 traQサーバーを再起動

しばらく待っても元に戻らないため、サーバーの再起動を行いました。
これによりtraQはとりあえず復旧しました。

19:45〜 原因の検討

サービスの復旧はしましたが、なぜ今回のような障害が発生したのかSysAd班内で検討を行いました。
traQのアクセスログはGCPのStack Driver Loggingに溜めており、そこでのレスポンスタイムやその他の利用状況から、画像アップロード時にメモリを大量に消費してしまいその結果Swapが発生してしまったのではないかという仮説が立てられました。
しかしtraQへの画像の投稿は毎日数十枚単位で行われており、なぜ今回発生したのかという明確な理由は見つけられませんでした。

わかりやすさのために時系列がバラバラです

20:40~22:00 再びアクセス不能に

断続的にtraQがCPU負荷の増大によりアクセスできなくなり、そのたびにコンテナの再起動により対応を行いました。

22:07 メンバーからの情報提供

メンバーから自身の操作が原因かもしれないとの情報提供がありました。

この情報提供により、以下のような原因でアクセス不能が発生したのではないかと仮説が再度立てられました。

1. ShowcaseコンソールからOpen Applicationを押したときに何らかの原因でtraQとShowcaseコンソールとの間で認証のためのリダイレクトループが発生する。
2. その結果、traQ起動時に取得するAPIを大量に叩きDoS攻撃のような状態に陥り、アクセス不能となった。

しかし、ここで不可解な点が存在しました。それは、Open Applicationで開かれるページはhttp://<リポジトリ名>.<ユーザー名>.trap.showなのに、Showcaseコンソール(https://shocase.trapti.tech)で行われるはずのリダイレクトが発生しているという点です。

そこで翌日、1年生の@sappi_redとともにこのような動作をする理由を探ってみました。
原因を追っていく流れはShowcaseの実装の中身にかなり依存していてとてもわかりにくいので割愛し、原因のみを書きたいと思います。

無限リダイレクトの発生原因

Giteaにコードがプッシュされてから実際にShowcaseにデプロイされるまでの流れは以下のようになっています。

1. ShowcaseがGiteaから通知を受ける
2. リポジトリをクローンしshowcase.yamlファイルがあるか確認する
3. showcase.yamlを元にNginxの設定ファイル・Dockerコンテナの起動コマンドを生成
4. 起動コマンドを実行し、Dockerコンテナを起動
5. Nginxの設定をリロードして設定を反映
6. デプロイ完了

例えば、to-hutohuがexampleというリポジトリで、公開するポートを8080と設定してShowcaseにデプロイした場合Nginxの設定ファイルとDockerの起動コマンドは以下のようになります。

Nginx設定ファイル

server {
	server_name example.to-hutohu.trap.show;
	location / {
		include proxy.conf;
		proxy_pass http://example.to-hutohu.trap.show:8080;
	}
    # 中略
}

Docker起動コマンド

$ docker run /* 中略 */ --network="trap.show" --hostname="example.to-hutohu.trap.show" runtime

Nginxのproxy_passにホスト名を指定した場合、設定のロード時にDNSの名前解決を行いTTLに関係なくその値を保持し続けます。(参考: nginx の proxy_pass の闇：株式会社サブスレッド)
通常の動作では、Nginxの設定をロードしたときにexample.to-hutohu.trap.showの名前解決を行い、NginxもDockerネットワーク内にいるので(4)で起動したコンテナのIPアドレスで解決されコンテナに対してルーティングが行われるようになります。

しかし、(4)でコンテナを起動した直後にコンテナが停止してしまった場合に意図しない動作が発生します。
(5)のNginxの設定読み込みの時に同様に名前解決が行われますが、すでにコンテナは停止してしまっているため得られるIPアドレスはshowcase.trapti.techのAレコードとなってしまいます。(showcase.trapti.techを@.trap.showのCNAMEに設定しているため)

ここで、公開するポートがShowcaseコンソールのポート(8080)と一致しているとShowcaseコンソールにルーティングされてしまいます。
更に、通常8080番ポートは閉じているためNginxを経由しない外部からのアクセスは受け付けませんが、同一サーバー内からのアクセスとなるためShowcaseコンソールはリクエストを受け付けてしまいます。

http://example.to-hutohu.trap.showでアクセスしてきたCookieにはhttps://showcase.trapti.tech向けに発行されたJWTは載っていません。
したがって、Showcaseコンソールでの認証は失敗し、http://example.to-hutohu.trap.showをリダイレクト対象としてtraQにJWTを発行するようリダイレクトします。
traQはJWTを再度発行し、http://example.to-hutohu.trap.showにリダイレクトしますが、発行されたトークンはhttps://showcase.trapti.techのCookieに対するものなので、また認証に失敗し無限リダイレクトが発生していまします。

以上のような流れで、ShowcaseとtraQの間で無限リダイレクトが発生します。
その結果、traQの起動時に叩かれるAPIが大量に呼ばれtraQのアクセス不能が引き起こされることがわかりました。

根本原因の対応

再発防止のため、各サービスに対して対応を行いました(一部予定も含む)。

• traQ

  • 起動時のAPIにキャッシュを追加
    • GetUsersとGetStampsのゼロタイムキャッシュ by wtks · Pull Request #724 · traPtitech/traQ
  • traQのJWT発行部分のリダイレクト先ドメインに制限を追加

• Showcase

  • Showcaseコンソールでの認証失敗のリダイレクト時に、Originを確認し管理画面のドメインでアクセスしてきているかを確認しリダイレクトするかを判断するように
  • ポートのバインド設定を変更

まとめ

この記事では、SysAd班で運用しているサービスで起こった障害とその原因究明・対応について書きました。
かなり多くのサービスが複雑に絡み合った結果の障害だったので、原因を究明できたときの達成感はひとしおでした。
わかりにくかったかもしれませんが少しでもSysAd班での活動の様子が伝わればうれしいです。

traP SysAd班では継続的にサービスを運用していくために、こういった障害への対応や日頃の保守の作業内容をWikiにまとめるようにしています。
今回の記事も、Wikiの内容を元に書いているものです。
私は今年度で卒業してしまうため、SysAd班に実際に関われるのは残り数ヶ月しかありませんが、長くtraPのインフラを維持できるようなしくみを整えられるように最後まで頑張って活動していきたいと思います。

この記事は遅刻して公開されているためもう26日目の記事は公開されていますが、明日は、11agateのWebGLに触れてみませんかです！
お楽しみに！