[TOC]

# 概要

2時間に1度、Webサーバにアクセスできなくなる（応答時間が長く、タイムアウトになる）。

mstdn.maud.io、mstdn.nere9.help で同様のことが発生している。

再起動後を行っても、間隔は変わらず、前回応答が停止したあと2時間くらいでこの問題は再現している。

<!-- fixme: どのコンテナを再起動したときですか？ -->
web,streaming,sidekiqのコンテナを再起動しても、再起動後2時間ではなく最後の詰まりから2時間のタイミングで発生した。

# 予想

## 特定のサーバとのサーバ間通信によるもの

特定のサーバと連合することによって発生する。「特定のサーバ」に該当する条件には、以下のようなものが考えられる。

- サーバがネットワーク的に不安定である
- 特定バージョン以上のMastodonと相性が悪い

## Mastodonのアップデートによるもの

## データベースの相性問題など

「一時的に、コネクションプールの値を極端に上げて、発生傾向の変化を見る」　によって、 `DB_POOL` の値が発生頻度に影響が出ることがわかった。postgresqlか、アプリケーションサーバの同DBのドライバのアップデートによって引き起こされている可能性が有る。

## 自宅ネットワーク問題

末代・nere9で全く同じような事象が発生しているので、あひるの家の問題である可能性は低い。

## psqlのパフォーマンス低下
pgrepackを実行する。

→1月はじめのサーバ移行でpg_dumpとrestoreを行っているため、効果がないと判断。

# 測定すべき事項

## [DOING] pumaのコンテナを増やす（スケールアップ又はオートスケール）

大規模サーバで発生していないこと、特定のサーバからのincomingが引き金になっていることから、pumaのコンテナを増やすことで全体としての停止時間を緩和できるかもしれない。

docker-compose up の --scale オプションなどを使い、pumaのコンテナを増やす。
その後、それらのワーカーにロードバランサが正しく分配する。

### 結果
* ステージングをscale 2で展開。動作の確認はできた。~~caddyのログの調整をし次第本番機にscale 8で展開予定。~~
* 本番機にも適用した。scale 8で展開。
* caddyのログはv1のバグでログからupstreamのipが分からない。v2に上げる必要がある。

## [DOING] nginxでレスポンスタイムを計測する

特定のサーバからのincomingが引き金になっていることから、その接続が非常に遅い疑いがある。

nginxで、全てのリクエストの（可能ならActivityPubのエンドポイントの）応答速度や5xx系エラーの数などを測定する。

今回注目したい接続は

- 応答時間が長いActivityPubエンドポイントへのincoming
- コネクションがエラーにならず、ずっとキープされている

ようなもの。

### 結果
* caddyのログにlatencyを記録するようにした。再発するまで待つ。

## [DONE] nginx、railsのリードタイムアウト時間の確認

「nginxでレスポンスタイムを計測する」より、そもそもサーバのリードタイムアウトの設定が気になるため、変更するかはともかく何秒に設定しているかを確認する。

場合によっては、この秒数を厳しくすることで緩和できるかもしれない。

### 結果
#### caddy
caddy では IdleTimeout はデフォルトの5分、その他のread,writeはデフォルトで無効化されている。（設定されてない）

#### rails
puma はデフォルト値として20秒が設定されている。

## [DONE] 停止前と停止後のPIDの変化

プロセスがハングアップしてリスポーンしている可能性を確認する。明確にこのタイミングでリスポーンするのであれば、そのサービスが問題を引き起こしている可能性が高いため、優先してログを確認する。

調査は、以下のコンテナに対して `docker top` などを停止の前後で実行すると良さそう。

- nginx
- puma
- postgresql

### 結果
- nginx
- 使っていない
- puma
- ワーカー含めて詰まりの前後でのpidの変化なし
- postgres
- 詰まり以外のタイミングでもプロセスは増減することは確認しているが、詰まりが発生する際は必ずワーカープロセスが生成されていることは観測した範囲では必ず起こっている

## [DONE] 問題が発生しているサーバとの発生時刻の傾向

以下のサーバについても監視を同時に行い、s25tの問題との傾向の類似性を確認する。

- mstdn.maud.io
- mstdn.y-zu.org（shibafu対応済み）
- mstdn.nere9.help（shibafu対応済み）

### 結果
~~mstdn.y-zu.org については発生していない。~~(20/02/06より発生するようになった)
mstdn.maud.io 及び mstdn.nere9.help に関しては social.mikutter.hachune.net(s25t) とかなり近しい発生頻度となっている。
例えばs25tで頻繁に発生している時間帯では他の2つのサーバーも頻発している。
s25tの頻度が通常に戻った前後で2つのサーバーも戻るといった挙動を示している。
以下にその傾向がみられる記録を示す。

## [PENDING] 一時的に、pumaのワーカー数を極端に上げて、発生傾向の変化を見る

コネクションプールの値を上げると頻繁に停止することがわかってるため、まともな結果が得られない可能性がある。

## [PENDING] 一時的に、sidekiqのワーカー数を極端に上げて、発生傾向の変化を見る

コネクションプールの値を上げると頻繁に停止することがわかってるため、まともな結果が得られない可能性がある。

## [PENDING] pumaの `persistent_timeout` 値を上げてみる

https://taruntarun.net/@mayaeh/103549547696299306
pumaの `persistent_timeout` 値はデフォルトで20(sec?)らしいが、これを変えることで挙動が変わるのではないかというもの。
仮に試すとしてどういった値にすべきか（webサーバーより長くなければならないのか短くなければならないのか）など指標が欲しい。（とりあえずいくつか試すという手はある）

## [DONE] pumaのバージョンを下げてみる
11/12のマージ前のバージョンに戻してみる。

また、pumaのissueとして https://github.com/puma/puma/issues/1628 があり、これが現象と一致するため原因ではないかと疑っている。

参考までに以下にpumaのバージョン履歴を載せる。

### 結果
何も変わらなかった

# 行った実験・測定

## 一時的に、コネクションプールの値を極端に上げて、発生傾向の変化を見る

pumaのコンテナの `DB_POOL` の値を5から50に引き上げた

### DB_POOLの適用されたコンテナ
<!-- fixme: `DB_POOL` はpumaのコンテナですか？ -->
`.env.production` で `DB_POOL` を設定したため、web,streaming,sidekiqのコンテナに環境変数として反映されている。

### DB_POOLの値を上げた期間
<!-- fixme: 何時から何時まで、DB_POOLの値を50にしましたか？ -->
1/25 20:30 から 1/25 23:00 までの間、`DB_POOL` の値を5から50に上げた。
1/25 23:00 に `DB_POOL` を削除してコンテナを再起動したところ、 `DB_POOL` 設定前の頻度に戻った。

# 時系列

|日付 |内容|
|:-------------|:---|
|2019/11/12 |リモートのmasterをマージ|
|2019/11/13 |announcementsの修正コミット|
|2019/12/24 |詰まりの現象が顕著に現れだす|
|2020/01/12 |サーバーの移行|
|2020/01/21 |master追従するが詰まりは解消せず|
|2020/01/24 |Zabbixの記録より詰まりに周期性があることが判明する|
|2020/01/25 |20:30にDB_POOLの値を5から50に上げた。|
|2020/01/25 |DB_POOLを上げたことにより、詰まりの頻度が大幅に増え、運用に支障が出たため23:00にDB_POOLを戻した。|
|2020/01/28 |master追従するが詰まりは解消せず|
|2020/02/02 |pumaのバージョンを4.3.1から4.2.0に下げてみた（発生していなかった頃のバージョン）。20時05分に適用。|
|2020/02/02 |21:53に詰まりがほぼ定刻に発生した。|
|2020/02/03 |19:00にpumaのバージョンを戻した|
|2020/02/06 |12:00にYづドンでも発生を確認。その後深夜に数回観測している。|

# その他情報

- しはぶの外形監視ログによると、12/24からこの問題が発生している。
- [2019/12/25〜2020/01/13の記録]( https://social.mikutter.hachune.net/users/shibafu528/statuses/103475935506540704) (※ この記録では多くが15分の障害として記録されているが、これは 2020/01/12 14:00 まではポーリング間隔が15分であったため)
- [2020/01/12〜2020/01/22の記録](https://docs.google.com/spreadsheets/d/1nRxGgrBhMBE7Mlrb-KD7OpnbanEE2s8iHOEUqJ4omLo/edit?usp=sharing)
- 12/24の前に、social.mikutter.hachune.netのコードをアップデートしたのは11/12
- https://github.com/tootsuite/mastodon/compare/master...Na0ki:master

<!-- fixme: 結局、12月24日にはアップデートしてますか？ -->
- 12/24にはアップデートしていない

- しばふによるsocial.mikutter.hachune.netなどの外形監視
- https://gf.ertona.net/
- 監視対象の h.kokuda.org は、アプリケーションのバージョンは3.0.1で、問題の切り分けのために監視している。

- stagingでは発生していない。
- stagingはサーバースペック以外はほぼ同じ構成となっている。
- まれにstagingは502を返すが本番機では起こっていない。

- htop, dstat, mackerel等でメトリクスの監視を行っていたが、詰まり発生時にスパイクが発生するなどはなかった。
- 例外として当然ではあるがTCPのcloseは増えている。

- 外形監視には引っかからない程度のタイムアウトは何度も起きている。

- 1/26 17:50 より頻度が多くなった。
- この前後で設定の変更はしていない。
- 30分に一回くらいのペースで発生しているが2時間のときと比べて発生時刻に振れ幅がある（±10分弱）