2019年11月26日 | ブログ記事

部内製チャットサービス「traQ」とPaaS基盤「Showcase」の障害対応の話【AdC2019 25日目】

to-hutohu

この記事は東京工業大学デジタル創作同好会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/traQtraPtitech/traQ_R-UIで開発を進めています。

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

Showcase

image-1489654331966

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

----------2019-11-26-4.20.50

Showcaseの管理画面(以下、Showcaseコンソール)の様子

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

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

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

----------2019-11-26-5.17.21

認証が行えなかった場合は、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 障害確認

image-1

(9:15ではなく19:15のミスですね)

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

----------2019-11-26-3.32.49

S512サーバーのSwapとCPUのログ

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

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

image--1--1

19:45〜 原因の検討

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

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

image--6-

Stack Driver Loggingのログからレスポンスが遅くなったエンドポイントを探した結果

image--7-

traQはメモリ512MBというクソ雑魚サーバーの上に他のサービスと同居する形で運用されています

image--2-

image--5-

障害直前までbooQに備品を登録する作業を行っていました
booQについては部内の備品・書籍管理サービスbooQの新規開発 | 東京工業大学デジタル創作同好会traPを御覧ください

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

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

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

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

image--9-

その日はtraQのBotを作るのが流行っており、複数人がWikiのBotの作り方記事を参考にShowcase上にtraQ Botをデプロイしていました

image--10-

Open ApplicationはShowcaseコンソールにあるボタンで、ここをクリックするとhttp://<リポジトリ名>.<ユーザー名>.trap.showが開かれます。

image--11-

image--12-

H101はShowcaseがデプロイされているサーバーです

image--14-

image--16-

1年生がログをシュッと探してきてくれてすごい

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

  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に対するものなので、また認証に失敗し無限リダイレクトが発生していまします。

----------2019-11-26-5.46.54

リダイレクトループの流れ ⑥以降は無限ループ

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

根本原因の対応

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

まとめ

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

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

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

この記事を書いた人
to-hutohu

traP16のとーふとふです。 こころ大好き 大岡山に来たらこころを食べましょう!!!!!

この記事をシェア

このエントリーをはてなブックマークに追加

関連する記事

2019年12月4日
部内製チャットサービス「traQ」UIのこれまで 【AdC2019 35日目】
spa
2019年12月1日
traP部内サービス「booQ」で発見した脆弱性でOSSコントリビュートした話
nagatech
2019年12月1日
「traPに入ってから半年が経ちました。」【AdC2019 31日目】
temma
2019年11月2日
traQのmarkdownのパースをWeb Workerでやるようにした話【アドベントカレンダー2019 3日目】
sappi_red
2019年12月11日
円周率が無理数であることの証明【AdC2019 42日目】
Tarara
2019年12月11日
ぷよぷよってナンですか?【AdC2019 42日目】
arahi10

活動の紹介

カテゴリ

タグ