問題

透過 Passenger 的相關 HTTP Request 回應 503，出現下面錯誤訊息

1
Request queue full (configured max. size: 100)

原因

Passenger 使用多個程序 (Process) 來處理 HTTP 請求，預設為 6 個。當大量 Request 進來時，處理不及的會先放在 Queue 等待處理，預設 100 個，當超過 Queue 的上限時會出現這錯誤。

處理請求速度不夠，來不及消化是出現錯誤的原因，然而處理速度不夠的原因就有很多可能，而對應的解決方式也都不同。這邊列出幾個我想得到的原因：

  1. 設定問題
  2. 程式效能問題
  3. 大量 HTTP 請求
  4. 程式存在 Bug
  5. 底層框架或套件有 Bug

網路上可能會看到有人說去修改 passenger_max_request_queue_size 的設定，來增加 Queue 的大小，但這沒有根本解決問題，還是要找出原因來對做應處理。

設定問題

說明

比較常見的是 Passenger 使用 ActionCable 時設定沒有正確。ActionCable 使用 Socket 持續連線，所以會常時佔用程序，以預設情況為例，當六個 ActionCable 連線建立之後，將會一直佔用 Passenger 的六個程序，後面再有任何 Request 進來都會卡在 Queue 裡面沒有回應。

解決方案

ActionCable 必須使用 Passenger 的 passenger_force_max_concurrent_requests_per_process 設定讓一個程序能處理多個連線。以下為 nginx 中的設定範例：

1
2
3
4
location /cable {
  passenger_app_group_name my_action_cable_group_name;
  passenger_force_max_concurrent_requests_per_process 0;
}

/cable 是你 ActionCable 的路徑，使用 passenger_app_group_name 讓 ActionCable 有一組獨立的 Passenger App，並且讓 passenger_force_max_concurrent_requests_per_process 設定只作用在 ActionCable 的程序。

程式效能問題

說明

程式效能不好造成處理時間太久，自然會有可能處理不及 HTTP 請求，最後出現 503 錯誤。

解決方案

提升程式效能的方法就很多了，可以在網路上找到許多相關的文章，這裡就不做太多說明。

大量 HTTP 請求

說明

其實還是和上面的問題一樣，你把程式進行優化，可能是把請求上限從 100 提升到 10000，但今天可能來 1000000 個請求，還是沒辦法支撐。

解決方案

限制連線

有時候大量的請求，可能是不正常的 DDOS 攻擊，當然也有可能是自己前端程式寫錯，我們可以限制 IP 同一時間的連線數或短時間內的請求次數。由於 Passenger 本身對這部分沒有提供相關的功能，我們可以借助其他服務來達成。可依據自己使用的系統架構來做設定，這邊簡單舉幾個例子：

  1. 使用 Nginx 限制連線數。
  2. 使用 Nginx 限制請求速率。
  3. 使用 Cloudflare 來限制連線。

之後有時間再另外寫更詳細的說明。

負載平衡

無論是不是被攻擊，也可以考慮使用負載平衡的方式處理，使用多台機器來處理大量的請求。

程式存在 Bug

說明

由於 Passenger 預設沒有 Timeout 機制，所以進入 Rails 應用運行的時候，不管程式跑多久他都會等他跑完。一旦程式有 Bug 出現無窮迴圈之類的情形，他會永遠的佔用該程序，最終造成 503。關於 Timeout 的機制，後面的章節會做進一步說明。

解決方案

當然解決掉 Bug 就能解決問題，不過有些 Bug 總是在特殊情況下才出現，所以如何有效地監控和追縱將會是這裡的重點。由於篇幅較長，獨立在後面的章節進行說明。

底層框架或套件有 Bug

說明

除了上層的應用與使用到的套件可能有問題之外，雖然機率不高，但也有可能是更底層的 Bug。例如之前的 Passenger 某個版本存在 Bug，在某些特定情況下會造成 Proccess 卡住沒有回應。

解決方案

這部分通常難以除錯，只能試試看升級或降級可能影響的框架或套件版本。

Timeout 機制

前面說了 Passenger 預設沒有 Timeout 機制，實際上他有 passenger_max_request_time 這個設定，但是是付費的 Enterprise 版本才有。

我們可能會想嘗試從 Nginx 之類的地方做 Timeout 的設定，經過我實測和研究得到以下結論：

  1. Nginx 的 Timeout 不作用在 Passenger 處理的 Request。
  2. Nginx 的 Timeout 作用在使用 Proxy 的 Request，例如使用 Puma，但 Request 運算仍然不會結束，僅是客戶端看到中斷。
  3. Puma 也沒有內建的 Timeout 設定，所以更換成 Puma 也不能解決。
  4. Cloudflare 處理的 Request 有 100 秒的 Timeout 時間，和 Nginx 一樣僅是客戶端看到中斷。

由於 Nginx 和 Cloudflare 所觸發的 Timeout 並不能中斷執行來釋放被佔用的程序，所以可以不用考慮作為解決問題的方法。有找到一個套件 rack-timeout 在應用層來處理 Timeout，不過文件中不斷強調這個方式存在巨大風險，所以我也沒有進一步研究下去。而實際上使用 Timeout 本身是治標不治本的做法，要解決根本問題，最終還是要從程式的效能和解決 Bug 下手。

Passenger 狀態與除錯

Passenger 提供了一個指令來顯示運行狀態，利用這個指令可以做後續的監控和除錯。輸入：

1
passenger-status

大概會看到下面的訊息：

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
Version : 6.0.0
Date    : 2024-06-15 09:35:48 +0000
Instance: Abtsf2Uy (nginx/1.17.0 Phusion_Passenger/6.0.0)

----------- General information -----------
Max pool size : 6
App groups    : 2
Processes     : 6
Requests in top-level queue : 0

----------- Application groups -----------
/home/user/app/current (production):
  App root: /home/user/app/current
  Requests in queue: 0
  * PID: 1311918   Sessions: 0       Processed: 317214   Uptime: 3d 2h 51m 7s
    CPU: 2%      Memory  : 150M    Last used: 0s
  * PID: 1312010   Sessions: 0       Processed: 144336   Uptime: 3d 2h 51m 5s
    CPU: 1%      Memory  : 165M    Last used: 16s
  * PID: 1312123   Sessions: 0       Processed: 95865   Uptime: 3d 2h 51m 5s
    CPU: 0%      Memory  : 139M    Last used: 16s
  * PID: 1312143   Sessions: 0       Processed: 82666   Uptime: 3d 2h 51m 4s
    CPU: 0%      Memory  : 135M    Last used: 16s
  * PID: 1312165   Sessions: 0       Processed: 75550   Uptime: 3d 2h 51m 3s
    CPU: 0%      Memory  : 142M    Last used: 16s

my_action_cable_group_name:
  App root: /home/user/app/current
  Requests in queue: 0
  * PID: 1312190   Sessions: 7       Processed: 3295    Uptime: 3d 2h 51m 1s
    CPU: 0%      Memory  : 194M    Last used: 34s

上面正常情況 Requests in queue 應該不會太多，而出現 503 錯誤的時候應該會是 100。其中 Sessions 是當前開啟的連線數，因為我們有做上面提到的 ActionCable 設定，所以有獨立的一個 my_action_cable_group_name，可以看到他目前有 7 個連線。

如果我們在出現 503 錯誤或是網站回應速度很慢的時候來看，可能會看到下面狀態：

1
2
3
4
5
6
7
8
9
10
11
12
13
/home/user/app/current (production):
  App root: /home/user/app/current
  Requests in queue: 57
  * PID: 1224694   Sessions: 1       Processed: 441208   Uptime: 21h 15m 48s
    CPU: 16%     Memory  : 147M    Last used: 0s
  * PID: 1224715   Sessions: 1       Processed: 59918   Uptime: 21h 15m 48s
    CPU: 14%     Memory  : 132M    Last used: 8h 12
  * PID: 1224734   Sessions: 1       Processed: 29658   Uptime: 21h 15m 48s
    CPU: 13%     Memory  : 130M    Last used: 8h 12
  * PID: 1224753   Sessions: 1       Processed: 26740   Uptime: 21h 15m 48s
    CPU: 13%     Memory  : 130M    Last used: 8h 11
  * PID: 1224794   Sessions: 1       Processed: 24562   Uptime: 21h 15m 44s
    CPU: 13%     Memory  : 125M    Last used: 8h 11

這個是還沒出現 503，但網站變很慢的情況。我們可以看到除了第一個程序的 Last used 是 0s 之外，其他都是八小時前，而且 Sessions 都是 1。這表示了八小時前，後面四個程序出現了特定的請求，造成他卡住到現在，整個網站只剩一個程序還可以運作。

這時候我們可以透過以下指令，來確認到底那些卡住的程序在執行什麼：

1
sudo passenger-status --show=requests

會輸出很大的 JSON 資料，利用上面有問題的程序 PID 去其中搜索，例如上面的 1224715，可以找到相關資料。節錄一小部分如下：

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
{
  "thread1": {
    "active_client_count": 27,
    "active_clients": {
      "1-229866": {
        "current_request": {
          "host": "example.com",
          "method": "GET",
          "path": "/path/of/controller/with/bug",
          "session": {
            "gupid": "1b4edc7-qk3zxPMg1m",
            "pid": 1224715
          },
          "started_at": {
            "local": "Tue Jun 11 15:51:01 2024",
            "relative": "8h 11m 47s ago",
            "relative_timestamp": -29506.706709623337,
            "timestamp": 1718121061.9029751
          },
        },
      },
    }
  }
}

其中可以看到他是執行 GET /path/of/controller/with/bug 這隻程式卡住的，而開始執行的時間為 Tue Jun 11 15:51:01 2024，可以去檢查這時間附近的 log 來進一步排除問題。最後，重啟 Nginx 或 Passenger 可以結束卡住的程序，讓系統恢復正常運作。

監控

我們可以利用 New Relic 之類的服務來分析應用的效能，但如果是無窮迴圈的 Bug，不知道 New Relic 有沒有辦法分析。而且如果程式存在有 Bug 會卡住的情況，可能要等網站掛掉了才會發現。一種 Workaround 的做法是，定期重啟服務，可以寫個 crontab 去重啟 Ningx：

1
sudo crontab -e

加入

1
0 * * * * /etc/init.d/nginx reload

這樣每小時會重啟一次，不過這樣可能沒辦法抓出有問題的程式。下面寫了一個簡單的程式，利用 relative_timestamp 判斷逾時的情況，並排除掉 ActionCable 的連線，在出現這情況的時候，記錄下有問題的 Request 和自動重啟，也可以執行自訂的行為：

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
#!/usr/bin/env node
const { execSync } = require('child_process');

// 自訂多久時間算逾時 (秒)
const TIMEOUT = 100;

// Log 存放位置，替換成自己的路徑
const LOG_FILE = '/path/to/log';

const output = execSync('sudo passenger-status --show=requests');
const json = JSON.parse(output.toString().substring(output.indexOf('{')));

const timeoutRequests = [];
for (const thread of Object.values(json)) {
  if (!thread.active_clients) {
    continue;
  }
  for (const client of Object.values(thread.active_clients)) {
    const request = client.current_request;
    if (!request.session || request.http_state !== 'COMPLETE') {
      continue;
    }

    const requestTime = Math.abs(request.started_at.relative_timestamp)
    if (requestTime > TIMEOUT) {
      timeoutRequests.push(request);
    }
  }
}

// 偵測到有逾時的時候
if (timeoutRequests.length) {
  // 自訂要執行的行為，發出警示等...

  // 紀錄有問題的 Request
  const paths = timeoutRequests.map((r) => `${r.method} ${r.path}`);
  execSync(`echo 'Timeout paths:\n${paths.join('\n')}' >> '${LOG_FILE}'`);

  // 重啟
  execSync('sudo service nginx reload');
}

可以用 crontab 每分鐘跑一次或跑一個背景程式來定時檢查，這可以取代上面 Workaround 定時重啟的做法。例如我們使用 crontab，將上面程式存為 check-passenger，然後修改權限：

1
chmod 755 check-passenger

加入 crontab

1
crontab -e

加入

1
* * * * * /path/to/check-passenger

替換成自己的路徑。

延伸閱讀

Nginx 限制連線數 (ngx_http_limit_conn_module)
Nginx 限制請求速率 (ngx_http_limit_req_module)