DQNEO日記

今日も明日も上昇気流

PHP5.6でphp-pecl-memcache経由でTokyoTyrantを使うとsession_startできないバグ

症状

session_start()を呼び出した時に、数十秒プロセスが固まった後にセッションが切れる。

つまり、会員ログインが必要なサイトで、ログイン直後にログインセッションが切れてログアウト状態になってしまうのです。

環境

$ yum info php
ame        : php
Arch        : x86_64
Version     : 5.6.0
Release     : 1.el6.remi.2
Size        : 8.6 M
Repo        : installed
From repo   : remi-php56
Summary     : PHP scripting language for creating dynamic web sites

$ yum info php-pecl-memcache
Name        : php-pecl-memcache
Arch        : x86_64
Version     : 3.0.8
Release     : 3.el6.remi.5.6
Size        : 336 k
Repo        : installed
From repo   : remi-php56
Summary     : Extension to work with the Memcached caching daemon
URL         : http://pecl.php.net/package/memcache
License     : PHP
TokyoTyrant/TokyoCabinetは こちらの拙作Cookbookでインストールしました。最新版が入ってるはずです。
https://github.com/DQNEO/cookbook-tokyotyrant

詳しい調査

straceとtcpdumpで PHPプロセスとTokyoTyrantの間の通信を見てみたところ、下記のようにincr,add,getを何度も何度もリトライして失敗しているように見えました。
straceの結果
nanosleep({1, 0}, NULL)                 = 0
select(18, [17], [17], NULL, {1, 0})    = 1 (out [17], left {0, 999995})
sendto(17, "incr f9c7437a25414b71cb1378b171532a638f3305d408238a5fdd308732e9eb8cd2.lock 1\r\n", 78, MSG_NOSIGNAL, NULL, 0) = 78
sendto(17, "add f9c7437a25414b71cb1378b171532a638f3305d408238a5fdd308732e9eb8cd2.lock 768 15 1\r\n1\r\n", 87, MSG_NOSIGNAL, NULL, 0) = 87
sendto(17, "get f9c7437a25414b71cb1378b171532a638f3305d408238a5fdd308732e9eb8cd2\r\n", 70, MSG_NOSIGNAL, NULL, 0) = 70
select(18, [17], [], NULL, {1, 0})      = 1 (in [17], left {0, 999998})
recvfrom(17, "27\r\nNOT_STORED\r\nVALUE f9c7437a25414b71cb1378b171532a638f3305d408238a5fdd308732e9eb8cd2 0 4148\r\nREMOTE_ADDR|s:10:\"10.10.81.1\";__anonymous__|b:0;expiretime|s:14:\"20140910193833\";...\"mai"..., 32768, 0, NULL, NULL) = 4250
nanosleep({1, 0}, NULL)                 = 0
select(18, [17], [17], NULL, {1, 0})    = 1 (out [17], left {0, 999996})
sendto(17, "incr f9c7437a25414b71cb1378b171532a638f3305d408238a5fdd308732e9eb8cd2.lock 1\r\n", 78, MSG_NOSIGNAL, NULL, 0) = 78
sendto(17, "add f9c7437a25414b71cb1378b171532a638f3305d408238a5fdd308732e9eb8cd2.lock 768 15 1\r\n1\r\n", 87, MSG_NOSIGNAL, NULL, 0) = 87
sendto(17, "get f9c7437a25414b71cb1378b171532a638f3305d408238a5fdd308732e9eb8cd2\r\n", 70, MSG_NOSIGNAL, NULL, 0) = 70
select(18, [17], [], NULL, {1, 0})      = 1 (in [17], left {0, 999998})
recvfrom(17, "28\r\nNOT_STORED\r\nVALUE f9c7437a25414b71cb1378b171532a638f3305d408238a5fdd308732e9eb8cd2 0 4148\r\nREMOTE_ADDR|s:10:\"10.10.81.1\";__anonymous__|b:0;expiretime|s:14:\"20140910193833\";..\"mai"..., 32768, 0, NULL, NULL) = 4250
nanosleep({1, 0}, NULL)
TokyoTyrantサーバのデバグログ
ttserverを起動するときに -ld オプションをつけるとデバグログが出力されます。
http://fallabs.com/tokyotyrant/spex.html#serverprog 
2014-09-10T20:10:06+09:00       INFO    connected: 127.0.0.1:57701
2014-09-10T20:10:06+09:00       DEBUG   doing mc_incr command
2014-09-10T20:10:06+09:00       DEBUG   doing mc_add command
2014-09-10T20:10:06+09:00       DEBUG   doing mc_get command
2014-09-10T20:10:06+09:00       DEBUG   doing mc_incr command
2014-09-10T20:10:06+09:00       DEBUG   doing mc_add command
2014-09-10T20:10:06+09:00       DEBUG   doing mc_get command
2014-09-10T20:10:06+09:00       DEBUG   doing mc_incr command
2014-09-10T20:10:06+09:00       DEBUG   doing mc_add command
2014-09-10T20:10:06+09:00       DEBUG   doing mc_get command
2014-09-10T20:10:06+09:00       DEBUG   doing mc_incr command
2014-09-10T20:10:06+09:00       DEBUG   doing mc_add command
2014-09-10T20:10:06+09:00       DEBUG   doing mc_get command
2014-09-10T20:10:06+09:00       DEBUG   doing mc_incr command
2014-09-10T20:10:06+09:00       DEBUG   doing mc_add command
2014-09-10T20:10:06+09:00       DEBUG   doing mc_get command
2014-09-10T20:10:07+09:00       DEBUG   doing mc_incr command
2014-09-10T20:10:07+09:00       DEBUG   doing mc_add command
2014-09-10T20:10:07+09:00       DEBUG   doing mc_get command
2014-09-10T20:10:07+09:00       DEBUG   doing mc_incr command
2014-09-10T20:10:07+09:00       DEBUG   doing mc_add command
2014-09-10T20:10:07+09:00       DEBUG   doing mc_get command
2014-09-10T20:10:07+09:00       DEBUG   doing mc_incr command
2014-09-10T20:10:07+09:00       DEBUG   doing mc_add command
2014-09-10T20:10:07+09:00       DEBUG   doing mc_get command
2014-09-10T20:10:08+09:00       DEBUG   doing mc_incr command
2014-09-10T20:10:08+09:00       DEBUG   doing mc_add command
2014-09-10T20:10:08+09:00       DEBUG   doing mc_get command
2014-09-10T20:10:09+09:00       DEBUG   doing mc_incr command
PHP本体およびpecl-memcacheのソースコードも読んでみましたが、自分の力量ではまったく何の手がかりも得られず・・

解決方法

pecl-memcacheが2013年以来更新されずに放置されていたので、もしやと思ってもう一個の似たようなモジュールである "pecl-memcached" の方を使ってみたら、見事に解決しました。 
$ yum install php-pecl-memcached
ini_set('session.save_handler', "memcached");
この現象の面白いところは、PHP5.5やPHP5.4では再現しないことです。
それから、PHP5.6でも接続先デーモンにTokyoTyrantではなくMemcachedを使った場合は再現しませんでした。
ふしぎー。
カテゴリ: PHP