CakePHPで同時アクセスするとプラグインが入れ替わる現象にハマった

CakePHP2.4.6で、異なる2つのプラグインに交互にアクセスすると、先にアクセスしたプラグインのエラーが後からアクセスしたプラグインへのアクセスで表示されるというポル現象にハマったのでメモ

再現手順

// cakeをcloneしてくる
$ git clone https://github.com/cakephp/cakephp.git
$ cd cakephp

$ git checkout 2.4.6

// なんでもいいのでプラグインを2つ置く
$ tree -d -L 2 app/Plugin/
app/Plugin/
├── Core
│   ├── Controller
│   ├── Lib
│   ├── Model
│   └── View
└── More
    ├── Controller
    ├── Lib
    ├── Model
    └── View

この2つのプラグインに対して連続アクセスすると、

$ wget http://localhost/core/test/ -O core.html;wget http://localhost/more/test/ -O more.html

--2015-10-30 15:24:13--  http://localhost/core/test/
localhost (localhost) をDNSに問いあわせています... 192.168.24.6
localhost (localhost)|192.168.24.6|:80 に接続しています... 接続しました。
HTTP による接続要求を送信しました、応答を待っています... 200 OK
長さ: 4 [text/html]
'core.html' に保存中

core.html 100%[=======================================>]       4  --.-KB/s 時間 0s

2015-10-30 15:24:18 (392 KB/s) - 'core.html' へ保存完了 [4/4]

--2015-10-30 15:24:18--  http://localhost/more/test/
localhost (localhost) をDNSに問いあわせています... 192.168.24.6
localhost (localhost)|192.168.24.6|:80 に接続しています... 接続しました。
HTTP による接続要求を送信しました、応答を待っています... 500 Internal Server Error
2015-10-30 15:24:24 エラー 500: Internal Server Error。

後からリクエストを投げたMoreプラグインのレスポンスが500で返ってくる

そして、そのまま時間を置いて(といっても10秒くらい)再アクセスすると200が返ってくる

nobiki@jessie:/var/tmp$ wget http://localhost/more/test/ -O more.html
--2015-10-30 15:24:39--  http://localhost/more/test/
localhost (localhost) をDNSに問いあわせています... 192.168.24.6
localhost (localhost)|192.168.24.6|:80 に接続しています... 接続しました。
HTTP による接続要求を送信しました、応答を待っています... 200 OK
長さ: 5 [text/html]
'more.html' に保存中

more.html 100%[=======================================>]       5  --.-KB/s 時間 0s

2015-10-30 15:24:44 (719 KB/s) - 'more.html' へ保存完了 [5/5]

ちなみにこれらのプラグインの中身は、echoしてexitするだけの単純な物です

$ cat core.html
core
$ cat more.html
more1

連続アクセスしてみる

2つのプラグインに対して負荷計測ツールを並列で実行してみてアクセスログを見てみる

$ siege -c 10 -r 15 http://localhost/more/test/ &
$ siege -c 10 -r 15 http://localhost/core/test/ &

アクセスログ（対応前）

後からリクエストを投げたプラグイン(Core)だけ、全て500エラーで返って来ているのを確認

172.17.42.1 - - [30/Oct/2015:11:29:14 +0900] "GET /more/test/ HTTP/1.0" 200 5 "-" "Mozilla/5.0 (pc-x86_64-linux-gnu) Siege/3.0.8"
172.17.42.1 - - [30/Oct/2015:11:29:14 +0900] "GET /more/test/ HTTP/1.0" 200 5 "-" "Mozilla/5.0 (pc-x86_64-linux-gnu) Siege/3.0.8"
172.17.42.1 - - [30/Oct/2015:11:29:13 +0900] "GET /core/test/ HTTP/1.0" 500 1210 "-" "Mozilla/5.0 (pc-x86_64-linux-gnu) Siege/3.0.8"
172.17.42.1 - - [30/Oct/2015:11:29:13 +0900] "GET /core/test/ HTTP/1.0" 500 1210 "-" "Mozilla/5.0 (pc-x86_64-linux-gnu) Siege/3.0.8"
172.17.42.1 - - [30/Oct/2015:11:29:13 +0900] "GET /core/test/ HTTP/1.0" 500 1209 "-" "Mozilla/5.0 (pc-x86_64-linux-gnu) Siege/3.0.8"
172.17.42.1 - - [30/Oct/2015:11:29:13 +0900] "GET /core/test/ HTTP/1.0" 500 1209 "-" "Mozilla/5.0 (pc-x86_64-linux-gnu) Siege/3.0.8"
172.17.42.1 - - [30/Oct/2015:11:29:14 +0900] "GET /more/test/ HTTP/1.0" 200 5 "-" "Mozilla/5.0 (pc-x86_64-linux-gnu) Siege/3.0.8"
172.17.42.1 - - [30/Oct/2015:11:29:13 +0900] "GET /core/test/ HTTP/1.0" 500 1210 "-" "Mozilla/5.0 (pc-x86_64-linux-gnu) Siege/3.0.8"
172.17.42.1 - - [30/Oct/2015:11:29:14 +0900] "GET /more/test/ HTTP/1.0" 200 5 "-" "Mozilla/5.0 (pc-x86_64-linux-gnu) Siege/3.0.8"
172.17.42.1 - - [30/Oct/2015:11:29:14 +0900] "GET /more/test/ HTTP/1.0" 200 5 "-" "Mozilla/5.0 (pc-x86_64-linux-gnu) Siege/3.0.8"
172.17.42.1 - - [30/Oct/2015:11:29:14 +0900] "GET /more/test/ HTTP/1.0" 200 5 "-" "Mozilla/5.0 (pc-x86_64-linux-gnu) Siege/3.0.8"
172.17.42.1 - - [30/Oct/2015:11:29:14 +0900] "GET /more/test/ HTTP/1.0" 200 5 "-" "Mozilla/5.0 (pc-x86_64-linux-gnu) Siege/3.0.8"
172.17.42.1 - - [30/Oct/2015:11:29:14 +0900] "GET /more/test/ HTTP/1.0" 200 5 "-" "Mozilla/5.0 (pc-x86_64-linux-gnu) Siege/3.0.8"
172.17.42.1 - - [30/Oct/2015:11:29:15 +0900] "GET /more/test/ HTTP/1.0" 200 5 "-" "Mozilla/5.0 (pc-x86_64-linux-gnu) Siege/3.0.8"
172.17.42.1 - - [30/Oct/2015:11:29:14 +0900] "GET /more/test/ HTTP/1.0" 200 5 "-" "Mozilla/5.0 (pc-x86_64-linux-gnu) Siege/3.0.8"
172.17.42.1 - - [30/Oct/2015:11:29:14 +0900] "GET /core/test/ HTTP/1.0" 500 1209 "-" "Mozilla/5.0 (pc-x86_64-linux-gnu) Siege/3.0.8"
172.17.42.1 - - [30/Oct/2015:11:29:15 +0900] "GET /more/test/ HTTP/1.0" 200 5 "-" "Mozilla/5.0 (pc-x86_64-linux-gnu) Siege/3.0.8"
172.17.42.1 - - [30/Oct/2015:11:29:14 +0900] "GET /core/test/ HTTP/1.0" 500 1208 "-" "Mozilla/5.0 (pc-x86_64-linux-gnu) Siege/3.0.8"
172.17.42.1 - - [30/Oct/2015:11:29:15 +0900] "GET /more/test/ HTTP/1.0" 200 5 "-" "Mozilla/5.0 (pc-x86_64-linux-gnu) Siege/3.0.8"
172.17.42.1 - - [30/Oct/2015:11:29:14 +0900] "GET /core/test/ HTTP/1.0" 500 1209 "-" "Mozilla/5.0 (pc-x86_64-linux-gnu) Siege/3.0.8"
172.17.42.1 - - [30/Oct/2015:11:29:14 +0900] "GET /core/test/ HTTP/1.0" 500 1209 "-" "Mozilla/5.0 (pc-x86_64-linux-gnu) Siege/3.0.8"
172.17.42.1 - - [30/Oct/2015:11:29:14 +0900] "GET /core/test/ HTTP/1.0" 500 1209 "-" "Mozilla/5.0 (pc-x86_64-linux-gnu) Siege/3.0.8"
172.17.42.1 - - [30/Oct/2015:11:29:15 +0900] "GET /more/test/ HTTP/1.0" 200 5 "-" "Mozilla/5.0 (pc-x86_64-linux-gnu) Siege/3.0.8"
172.17.42.1 - - [30/Oct/2015:11:29:15 +0900] "GET /core/test/ HTTP/1.0" 500 1209 "-" "Mozilla/5.0 (pc-x86_64-linux-gnu) Siege/3.0.8"
172.17.42.1 - - [30/Oct/2015:11:29:15 +0900] "GET /more/test/ HTTP/1.0" 200 5 "-" "Mozilla/5.0 (pc-x86_64-linux-gnu) Siege/3.0.8"
172.17.42.1 - - [30/Oct/2015:11:29:15 +0900] "GET /more/test/ HTTP/1.0" 200 5 "-" "Mozilla/5.0 (pc-x86_64-linux-gnu) Siege/3.0.8"
172.17.42.1 - - [30/Oct/2015:11:29:15 +0900] "GET /more/test/ HTTP/1.0" 200 5 "-" "Mozilla/5.0 (pc-x86_64-linux-gnu) Siege/3.0.8"
172.17.42.1 - - [30/Oct/2015:11:29:14 +0900] "GET /core/test/ HTTP/1.0" 500 1209 "-" "Mozilla/5.0 (pc-x86_64-linux-gnu) Siege/3.0.8"

どうしてこうなった

こちらで書かれている、「app以下のクラス名とPlugin以下のクラス名が同名だと誤動作する」という現象に非常に似ている

という事で、app/tmp/cache/persistent/cake_core_file_mapを消してみましたが、結果的にダメでした

暫定対応

最終的に、キャッシュ機能を使わないようにbootstrap.phpで設定

--- a/project/Config/bootstrap.php
+++ b/project/Config/bootstrap.php

-Cache::config('default', array('engine' => 'File','mask' => 0666));
+//Cache::config('default', array('engine' => 'File','mask' => 0666));
+
+Configure::write('Cache.disable', true);

アクセスログ（対応後）

全て200で返ってくるのを確認

172.17.42.1 - - [30/Oct/2015:12:06:15 +0900] "GET /more/test/ HTTP/1.0" 200 5 "-" "Mozilla/5.0 (pc-x86_64-linux-gnu) Siege/3.0.8"
172.17.42.1 - - [30/Oct/2015:12:06:15 +0900] "GET /more/test/ HTTP/1.0" 200 5 "-" "Mozilla/5.0 (pc-x86_64-linux-gnu) Siege/3.0.8"
172.17.42.1 - - [30/Oct/2015:12:06:15 +0900] "GET /core/test/ HTTP/1.0" 200 4 "-" "Mozilla/5.0 (pc-x86_64-linux-gnu) Siege/3.0.8"
172.17.42.1 - - [30/Oct/2015:12:06:15 +0900] "GET /core/test/ HTTP/1.0" 200 4 "-" "Mozilla/5.0 (pc-x86_64-linux-gnu) Siege/3.0.8"
172.17.42.1 - - [30/Oct/2015:12:06:15 +0900] "GET /more/test/ HTTP/1.0" 200 5 "-" "Mozilla/5.0 (pc-x86_64-linux-gnu) Siege/3.0.8"
172.17.42.1 - - [30/Oct/2015:12:06:15 +0900] "GET /more/test/ HTTP/1.0" 200 5 "-" "Mozilla/5.0 (pc-x86_64-linux-gnu) Siege/3.0.8"
172.17.42.1 - - [30/Oct/2015:12:06:15 +0900] "GET /more/test/ HTTP/1.0" 200 5 "-" "Mozilla/5.0 (pc-x86_64-linux-gnu) Siege/3.0.8"
172.17.42.1 - - [30/Oct/2015:12:06:15 +0900] "GET /core/test/ HTTP/1.0" 200 4 "-" "Mozilla/5.0 (pc-x86_64-linux-gnu) Siege/3.0.8"
172.17.42.1 - - [30/Oct/2015:12:06:15 +0900] "GET /core/test/ HTTP/1.0" 200 4 "-" "Mozilla/5.0 (pc-x86_64-linux-gnu) Siege/3.0.8"
172.17.42.1 - - [30/Oct/2015:12:06:15 +0900] "GET /more/test/ HTTP/1.0" 200 5 "-" "Mozilla/5.0 (pc-x86_64-linux-gnu) Siege/3.0.8"
172.17.42.1 - - [30/Oct/2015:12:06:15 +0900] "GET /core/test/ HTTP/1.0" 200 4 "-" "Mozilla/5.0 (pc-x86_64-linux-gnu) Siege/3.0.8"
172.17.42.1 - - [30/Oct/2015:12:06:15 +0900] "GET /more/test/ HTTP/1.0" 200 5 "-" "Mozilla/5.0 (pc-x86_64-linux-gnu) Siege/3.0.8"
172.17.42.1 - - [30/Oct/2015:12:06:16 +0900] "GET /more/test/ HTTP/1.0" 200 5 "-" "Mozilla/5.0 (pc-x86_64-linux-gnu) Siege/3.0.8"
172.17.42.1 - - [30/Oct/2015:12:06:15 +0900] "GET /core/test/ HTTP/1.0" 200 4 "-" "Mozilla/5.0 (pc-x86_64-linux-gnu) Siege/3.0.8"
172.17.42.1 - - [30/Oct/2015:12:06:16 +0900] "GET /core/test/ HTTP/1.0" 200 4 "-" "Mozilla/5.0 (pc-x86_64-linux-gnu) Siege/3.0.8"
172.17.42.1 - - [30/Oct/2015:12:06:16 +0900] "GET /more/test/ HTTP/1.0" 200 5 "-" "Mozilla/5.0 (pc-x86_64-linux-gnu) Siege/3.0.8"
172.17.42.1 - - [30/Oct/2015:12:06:16 +0900] "GET /more/test/ HTTP/1.0" 200 5 "-" "Mozilla/5.0 (pc-x86_64-linux-gnu) Siege/3.0.8"
172.17.42.1 - - [30/Oct/2015:12:06:16 +0900] "GET /core/test/ HTTP/1.0" 200 4 "-" "Mozilla/5.0 (pc-x86_64-linux-gnu) Siege/3.0.8"
172.17.42.1 - - [30/Oct/2015:12:06:16 +0900] "GET /core/test/ HTTP/1.0" 200 4 "-" "Mozilla/5.0 (pc-x86_64-linux-gnu) Siege/3.0.8"
172.17.42.1 - - [30/Oct/2015:12:06:16 +0900] "GET /core/test/ HTTP/1.0" 200 4 "-" "Mozilla/5.0 (pc-x86_64-linux-gnu) Siege/3.0.8"
172.17.42.1 - - [30/Oct/2015:12:06:16 +0900] "GET /more/test/ HTTP/1.0" 200 5 "-" "Mozilla/5.0 (pc-x86_64-linux-gnu) Siege/3.0.8"
172.17.42.1 - - [30/Oct/2015:12:06:16 +0900] "GET /more/test/ HTTP/1.0" 200 5 "-" "Mozilla/5.0 (pc-x86_64-linux-gnu) Siege/3.0.8"
172.17.42.1 - - [30/Oct/2015:12:06:16 +0900] "GET /core/test/ HTTP/1.0" 200 4 "-" "Mozilla/5.0 (pc-x86_64-linux-gnu) Siege/3.0.8"
172.17.42.1 - - [30/Oct/2015:12:06:16 +0900] "GET /more/test/ HTTP/1.0" 200 5 "-" "Mozilla/5.0 (pc-x86_64-linux-gnu) Siege/3.0.8"
172.17.42.1 - - [30/Oct/2015:12:06:16 +0900] "GET /core/test/ HTTP/1.0" 200 4 "-" "Mozilla/5.0 (pc-x86_64-linux-gnu) Siege/3.0.8"
172.17.42.1 - - [30/Oct/2015:12:06:16 +0900] "GET /more/test/ HTTP/1.0" 200 5 "-" "Mozilla/5.0 (pc-x86_64-linux-gnu) Siege/3.0.8"

Cakeのキャッシュやばいな(白目)

テーブルロックとかセッションとか散々探しまわったけどこれであっさり解決してしまった…