Cloudflare LB で WebSocket が突然切断される問題

ピン留めされたアイテム

voluntas

まとめ

Cloudflare LB で WebSocket は利用しない事にしました

問題の報告から 6 ヶ月以上経過しても、連絡も無く問題も継続して発生していました。
また 8 ヶ月目にやっと返信がありましたが、5 ヶ月前に修正されているとだけ連絡を貰いました。

何度も再現試験をして再現している旨を伝えましたが、直してるので再度検証してほしいと言われてしまいました。ちなみにログに関してはこちらから「ログは確認したのか？」と聞くまではスルーされました。

Cloudflare LB の WebSocket の突然切断されるのにプランは関係ない
- サポートから回答
Cloudflare LB の WebSocket のタイムアウトは 100 秒
- サポートから回答
Cloudflare 側は問題は把握しているが、すぐ解決できる感じではなさそう
- サポートからの返信で、まずはログの調査からという感じだった
- ログは提出済み
Cloudflare 側のデプロイで切断されるのは思った以上短い間隔で発生する
- 実際、数日の検証中に発生している
- これはドキュメントに掲載されていることで知っていたが数ヶ月とかのスパンだと思っていた

商用環境での Cloudflare LB 経由の WebSocket 利用を取りやめた。Cloudflare LB を利用しなければ数日間接続しっぱなしで、一本も切断されていない。

WebSocket の長時間接続を期待するサービスで Cloudflare LB を採用するのは、現時点では厳しい。気軽に張り直せるサービスであれば良いと思う。

Cloudflare LB で WebSocket を利用する際はしっかり検証してから採用する事をお勧めします。

voluntas

この資料は Cloudflare LB で発生している WebSocket が突然切断される問題をまとめたものです。

前提

問題が発生していたのは Pro プラン
今回の検証前に Business プランに入っている
- Volume of concurrent connections は High (important applications)
サポートにはすでにチケットを切って、問い合わせ済み

Cloudflareが新しいコードをグローバルネットワークにリリースすると、サーバーが再起動され、WebSocket接続が終了する場合があります。

短ければ数分、長くても 4 時間程度で切断される。もしこれがリリースによるサーバー再起動が影響しているなら、 Cloudflare LB での WebSocket は使い物にならないことになる。

問題

Cloudflare LB で WebSocket を利用するとランダムに切断される。

対策

Cloudflare LB にはどうやら proxy_read_timeout が 100 s らしいが、詳細な情報は公式には出ていない。ただし 30 秒間隔でサーバーから ping を送っているため、コレは回避しているはず。

さらに WebSocket ではこの ping 以外の通信は行っていない。

Cloudflare LB の後ろに Nginx がいるが、Nginx の proxy_read_timeout は 180 s に設定済み。

検証

Cloudflare LB 、Nginx 、なしで 10 接続それぞれブラウザから行い検証。

ブラウザ -> <WebSocket (over TLS)> -> Cloudflare LB -> <WebSocket (over TLS)> -> Nginx -> <WebSocket> -> 自社製品
ブラウザ -> <WebSocket (over TLS)> -> Nginx -> <WebSocket> -> 自社製品
ブラウザ -> <WebSocket> -> 自社製品

検証結果

vvv-cloudflare-lb のみが全て切断されており、それ以外は切断されていない。

それぞれの接続形式で 10 接続ずつ
それぞれの接続形式で channel_id (接続先)を変更している
- vvv-cloudflare-lb
- vvv-nginx
- vvv-sora
  - sora は自社製品名
ログを jq でフィルターしている
websocket_terminated_reason が {error,closed} が TCP が突然切断されたエラー

$ tail -f connection.jsonl | jq 'select(.channel_id == "vvv-cloudflare-lb" or .channel_id == "vvv-nginx" or .channel_id == "vvv-sora") | { channel_id, connection_id, created_timestamp, destroyed_timestamp, websocket_terminated_reason, signaling_terminate_reason }'
{
  "channel_id": "vvv-cloudflare-lb",
  "connection_id": "2TXVG8NKSS7BQ88FAXG4J6VPM8",
  "created_timestamp": "2023-07-14T09:25:19.952986Z",
  "destroyed_timestamp": "2023-07-14T09:29:04.003679Z",
  "websocket_terminated_reason": "{error,closed}",
  "signaling_terminate_reason": "{shutdown,{terminate_websocket_pid,normal}}"
}
{
  "channel_id": "vvv-cloudflare-lb",
  "connection_id": "NRBDAATZBN2WHE5H7Q1AXVGBY8",
  "created_timestamp": "2023-07-14T09:25:18.481723Z",
  "destroyed_timestamp": "2023-07-14T09:50:55.976540Z",
  "websocket_terminated_reason": "{error,closed}",
  "signaling_terminate_reason": "{shutdown,{terminate_websocket_pid,normal}}"
}
{
  "channel_id": "vvv-cloudflare-lb",
  "connection_id": "XG5T547SCD2CH7721GASG5PJ80",
  "created_timestamp": "2023-07-14T09:25:21.975458Z",
  "destroyed_timestamp": "2023-07-14T10:24:02.465605Z",
  "websocket_terminated_reason": "{error,closed}",
  "signaling_terminate_reason": "{shutdown,{terminate_websocket_pid,normal}}"
}
{
  "channel_id": "vvv-cloudflare-lb",
  "connection_id": "TRCCHVN3AS2CXF775YWCE9V91W",
  "created_timestamp": "2023-07-14T09:25:06.950377Z",
  "destroyed_timestamp": "2023-07-14T10:27:20.789938Z",
  "websocket_terminated_reason": "{error,closed}",
  "signaling_terminate_reason": "{shutdown,{terminate_websocket_pid,normal}}"
}
{
  "channel_id": "vvv-cloudflare-lb",
  "connection_id": "YBS3J1F0P547926DCH9CF0E610",
  "created_timestamp": "2023-07-14T09:25:09.927673Z",
  "destroyed_timestamp": "2023-07-14T10:32:19.451773Z",
  "websocket_terminated_reason": "{error,closed}",
  "signaling_terminate_reason": "{shutdown,{terminate_websocket_pid,normal}}"
}
{
  "channel_id": "vvv-cloudflare-lb",
  "connection_id": "Y3DNFRPNZ94VS8N5KNMN79GBDC",
  "created_timestamp": "2023-07-14T09:25:08.518745Z",
  "destroyed_timestamp": "2023-07-14T10:35:25.780366Z",
  "websocket_terminated_reason": "{error,closed}",
  "signaling_terminate_reason": "{shutdown,{terminate_websocket_pid,normal}}"
}
{
  "channel_id": "vvv-cloudflare-lb",
  "connection_id": "T6GHBJKVRH26X31FPYA8PM43K4",
  "created_timestamp": "2023-07-14T09:25:15.566448Z",
  "destroyed_timestamp": "2023-07-14T10:47:13.880008Z",
  "websocket_terminated_reason": "{error,closed}",
  "signaling_terminate_reason": "{shutdown,{terminate_websocket_pid,normal}}"
}
{
  "channel_id": "vvv-cloudflare-lb",
  "connection_id": "RHPXTMXY091QZ12DRNT8B276M8",
  "created_timestamp": "2023-07-14T09:25:23.879157Z",
  "destroyed_timestamp": "2023-07-14T11:33:01.480363Z",
  "websocket_terminated_reason": "{error,closed}",
  "signaling_terminate_reason": "{shutdown,{terminate_websocket_pid,normal}}"
}
{
  "channel_id": "vvv-cloudflare-lb",
  "connection_id": "E97E798VB13ES03QZ0GX3P4ERG",
  "created_timestamp": "2023-07-14T09:25:11.308730Z",
  "destroyed_timestamp": "2023-07-14T11:47:44.853650Z",
  "websocket_terminated_reason": "{error,closed}",
  "signaling_terminate_reason": "{shutdown,{terminate_websocket_pid,normal}}"
}

Cloudflare LB を経由している接続だけが、切断される。それもタイムアウト関係なく、ランダムに切断される。

同様の問題

java - Cloudflare Random WebSocket Disconnections - Stack Overflow
Socket.io randomly disconnecting - General - Cloudflare Community
- Cloudflare を経由すると切断されるという同じような問題
Websocket Disconnects - Website, Application, Performance / Security - Cloudflare Community

voluntas

調査メモ

たまに突然切断される問題があった
回線の不安定さかと思っていたが、やけに多いと感じていた

前提

自社製品は Erlang/OTP で書かれている
Cowboy という Erlang/OTP で書かれた HTTP / WebSocket サーバーを利用している
Cowboy は Ranch という TCP サーバーを利用している

調査

突然切断される場合は Cowboy で {error, closed} というエラーが出ていることが解った
Cowboy のソースを読むと {error, closed} は ranch で {tcp_closed, Socket} が起きると発生していた
Cowboy で {tcp_closed, Socket} は WebSocket の Close フレームを送受信するまえに TCP が切断されると発生する
ranch は gen_tcp のラッパー、{tcp_closed, Socket} は gen_tcp が出力している
{tcp_closed, Socket} が上がってきているということは、自社製品側から切断している可能性はとても低い

WebSocket の経路での切断を疑う

Nginx は proxy_read_timeout がデフォルト 60 s
- 180 s に引き延ばす
自社製品はサーバーからの ping/pong 機能はある
- 30 秒間隔で ping/pong

それぞれのパターンで接続してみる

経路毎に検証する。

Cloudflare LB -> Nginx
Nginx
なし

結果

Cloudflare LB -> Nginx の時のみ全て切断された。

追試

自社製品の ping/pon を 10 秒間隔に変更する
- 変わらなかったので 30 秒に戻した

結果

Cloudflare LB -> Nginx の時のみ全て切断された。

voluntas

WebSocket キャパシティプランニング

これはおまけです

Cloudflare で WebSocket を利用するばあい、プラン事に同時接続の量がふわっと決められています。

キャパシティプランニングのために詳細をサポートに聞いても「教えられない」「Business プランに入れ」とだけしか言われません。ちなみに当時は Pro プランでしたが、チケットも 1 ヶ月待たされます。残念。

ということで Cloudflare で WebSocket を利用したい場合、Business プラン以上、つまり年 $2400 以上を支払う前提で考えるのをお勧めします。ただし、2023 年 7 月時点ではランダムで切断される可能性があります。そのため 常時接続 を期待して Cloudflare LB 経由で WebSocket を使うのは避ける事をお勧めします。

Using Cloudflare with WebSockets · Cloudflare Support docs

voluntas

追試 : 2023-07-16

Pro プランでも同様の結果だったという Cloudflare コミュニティでの書き込みがあり、Business プランを契約して 1 日経過してから検証をすることにした。

仮説

Business プランに切り替えはすぐには反映されず、ある程度時間が経過しないと反映されないのではないかと考え約 1 日経過したあとに、検証を行った。

検証結果

ブラウザ -> Cloudflare LB -> Nginx -> 自社製品 という経路。ランダムに切断されていた検証と同様。

前回の検証と同様、10 接続を行う。11 時間と 15 時間で突然の切断が発生。

推測

こちらの推測は Cloudflare サポートからプランは影響しないとの連絡を頂いた

~~Business プラン、以上でないとランダムに WebSocket は切断される~~
- ~~Pro プランでランダムに接続されている人が自分以外にも存在していたため~~
- ~~サポートから「Business プラン」へ入れと強く言われたのも、コレが理由なのかも知れない~~
~~Business プランの反映はすぐにはされず、一定時間をおいて反映する。少なくとも契約後 12 時間以内ではランダムな切断は変わらず起きていた~~

voluntas

追試: 2023-07-17

Cloudflare LB / Nginx 経由それぞれに 10 接続
Cloudflare LB 経由 28 時間程度で 2 つ切断 (2/10)
Nginx 経由切断なし (0/10)

$ tail -f connection.jsonl | jq 'select(.websocket_terminated_reason == "{error,closed}") | { channel_id, connection_id, created_timestamp, destroyed_timestamp, websocket_terminated_reason, signaling_terminate_reason }'
{
  "channel_id": "vvv-cloudflare-lb-win",
  "connection_id": "6SGKJ3E15H2C94KC8PKRYJZWEC",
  "created_timestamp": "2023-07-16T00:40:50.212984Z",
  "destroyed_timestamp": "2023-07-17T04:06:34.283160Z",
  "websocket_terminated_reason": "{error,closed}",
  "signaling_terminate_reason": "{shutdown,{terminate_websocket,normal}}"
}
{
  "channel_id": "vvv-cloudflare-lb-win",
  "connection_id": "173252T2DH0C1FE5F9YQJM22FR",
  "created_timestamp": "2023-07-16T00:40:45.544673Z",
  "destroyed_timestamp": "2023-07-17T04:09:33.928997Z",
  "websocket_terminated_reason": "{error,closed}",
  "signaling_terminate_reason": "{shutdown,{terminate_websocket,normal}}"
}
{
  "channel_id": "vvv-cloudflare-lb-win",
  "connection_id": "JNZEN6WWPS6ZS9SJSAK9VA373M",
  "created_timestamp": "2023-07-16T00:40:12.131611Z",
  "destroyed_timestamp": "2023-07-17T04:21:20.953104Z",
  "websocket_terminated_reason": "{error,closed}",
  "signaling_terminate_reason": "{shutdown,{terminate_websocket,normal}}"
}
{
  "channel_id": "vvv-cloudflare-lb-win",
  "connection_id": "ZQXC2K6YNH3FH2M8J96XJAMSQ4",
  "created_timestamp": "2023-07-16T00:40:14.256657Z",
  "destroyed_timestamp": "2023-07-17T04:26:12.166227Z",
  "websocket_terminated_reason": "{error,closed}",
  "signaling_terminate_reason": "{shutdown,{terminate_websocket,normal}}"
}
{
  "channel_id": "vvv-cloudflare-lb-win",
  "connection_id": "ZZYPRVF4ED38HDC9Z90VHD4PBM",
  "created_timestamp": "2023-07-16T00:40:55.601097Z",
  "destroyed_timestamp": "2023-07-17T04:32:18.485738Z",
  "websocket_terminated_reason": "{error,closed}",
  "signaling_terminate_reason": "{shutdown,{terminate_websocket,normal}}"
}

雑感

似たようなタイミングで切断が発生し始めている
コレはもしかして Cloduflare 側のデプロイタイミングでの切断か？

voluntas

CloudFlare WebSocket proxy restarting

WebSocket proxy が再起動したときは、ちゃんとエラーメッセージがクライアントに出力されることがわかった。

voluntas

追記: 2023-07-20

Cloudflare サポートから返信。

ランダムな切断についてはプランによる影響はない
- これは明記されていないので、こちらも納得
Cloudflare LB のタイムアウトは 100 秒
- これは proxy_read_timeout と同じなので、納得

調査方法

https://developers.cloudflare.com/fundamentals/get-started/reference/cdn-cgi-endpoint/ の情報を送れ
- https://<domain>/cdn-cgi/trace でアクセス
https://developers.cloudflare.com/logs/instant-logs/ の情報を送れ
- ビジネスプラン以上じゃないと利用できない
- 60 分の制限あり
IP Address の情報を送れ

これらの情報を取得して再度共有して調査してもらう予定。

商用環境の切り替え

問題をすぐに解決できる雰囲気ではないので、商用環境では Cloudflare LB 経由での WebSocket は利用しないことにした。

Cloudflare 側のデプロイによる再起動が発生することもわかり、1-2 日程度の接続も厳しいと感じてはいる。

正直、とても残念な結果。

追試

Windows 11 Pro
Chrome 114
Cloudflare LB / Nginx 経由それぞれに 5 接続
/cdn-cgi/trace で IP 取得

結果

Cloudflare LB 経由が 6-10 時間程度で 3 本切断
Nginx の切断は 0 本

クライアント側では Code と Reason は出力されず、Cloudflare LB での突然の切断と判断。

$ tail -f connection.jsonl | jq 'select(.websocket_terminated_reason == "{error,closed}") | { channel_id, connection_id, created_timestamp, destroyed_timestamp, websocket_terminated_reason, signaling_terminate_reason }'
{
  "channel_id": "vvv-cloudflare-lb-win-2023-07-20",
  "connection_id": "3YSZSJRVAH559BPJ1Y3CXGMDK8",
  "created_timestamp": "2023-07-20T02:49:50.398303Z",
  "destroyed_timestamp": "2023-07-20T08:52:33.167178Z",
  "websocket_terminated_reason": "{error,closed}",
  "signaling_terminate_reason": "{shutdown,{terminate_websocket,normal}}"
}
{
  "channel_id": "vvv-cloudflare-lb-win-2023-07-20",
  "connection_id": "JTHJXS1RRX5A17XYSVYBN4VS44",
  "created_timestamp": "2023-07-20T02:49:48.699476Z",
  "destroyed_timestamp": "2023-07-20T10:50:35.838042Z",
  "websocket_terminated_reason": "{error,closed}",
  "signaling_terminate_reason": "{shutdown,{terminate_websocket,normal}}"
}
{
  "channel_id": "vvv-cloudflare-lb-win-2023-07-20",
  "connection_id": "5AR5PP9RYN7TS88BJYSR21QB38",
  "created_timestamp": "2023-07-20T02:49:45.032030Z",
  "destroyed_timestamp": "2023-07-20T12:21:20.524820Z",
  "websocket_terminated_reason": "{error,closed}",
  "signaling_terminate_reason": "{shutdown,{terminate_websocket,normal}}"
}

Cloudflare LB を経由しない WebSocket 接続

別途、検証用に Nginx 経由のみで繋いでいる接続は 10 接続とも 4 日以上接続が継続していた。

voluntas

追記: 2023-08-02

Cloudflare サポートにログを 2 週間前に提出済み
そろそろ再試験をやるか検討している

サポートから返信が来る

サービスの最大同時接続数または平均同時接続数について質問される。Cloudflare LB を利用していなければ問題は発生していないと回答しているのにスルーされている。

むしろ検証環境用に Cloudflare LB のノードプール契約してるので、多くても 20 接続程度 ...。

再度問題を整理して返信。解決してほしいのは「Cloudflare LB を利用している際に突然 WebSocket が切断してしまう問題」と回答。

そもそも 2 週間前に提出したログへの反応がなかったので、ログの調査は進んでいるかと確認。

voluntas

追記: 2023-08-09

Cloudflare サポートにログを提出して 20 日が経過
前回の見当違いな返答がきてから 7 日が経過
問題を解決する気があるのか確認の返信をした

voluntas

追記: 2023-08-21

問い合わせてから 1 ヶ月以上経過
全く進展なし
返信もなし

voluntas

追記: 2023-08-29

問い合わせてから 1.5 ヶ月以上経過
返信なし
発生しづらくはなっているようだが再現あり

追試

{
  "channel_id": "cloudflare",
  "connection_id": "APTZJ3RM6935F50E67H007N6JM",
  "created_timestamp": "2023-08-23T01:02:28.487303Z",
  "destroyed_timestamp": "2023-08-24T10:00:42.504471Z",
  "websocket_terminated_reason": "{error,closed}",
  "signaling_terminate_reason": "{shutdown,{terminate_websocket,normal}}"
}

再現している。

voluntas