curlでPOST送信する場合に注意しておいた方がいいこと(続・CentOS4系と5系のcurlの違い)
以前のエントリで調査したcurlのバージョンの違いについてその後色々調べたので結果をまとめてみる。
おさらい
サーバの移行を行ったところ、curlの通信に著しい遅延が発生した。具体的に言うと1回の通信で2秒かかる。
前回の対策としてはとりあえずCentOS4系のSRPMを持ってきてビルドし、バージョンをダウングレードして対応した。
調査
実は前回のエントリでは環境を正確に書ききっていなかったorz。
今回調査を続けた結果以下の環境でのみこの2秒遅延が起こることが判明した。
確認したこと
curl
まずcurlだけど、最初は7.12と7.15のChangeLogを追っかけて何かそれらしき変更が加わったのかを調べたんだけど、特定しきれなかった。
そこでどのバージョンで変化が起こるかを確認してみた。
手順としては
- php 5.2.8の環境があったので、curlのバージョンを変えながらテスト
- curl-7.12.0をソースからコンパイルしてPHPの再コンパイル
- poundサーバに向けて遅延が発生したデータをPOSTしても再現されず
- curl-7.13.0で同様の手順を行ったところ遅延発生
というわけで7.12.0〜7.13.0の間で何かがかわったっぽいというのが判明。
Pound
- Pound 2.4.4 と 2.4.5
この時点ではPoundが関係しているとはわかっていなかった。
ここでPoundのログを見ていたときに、2秒掛かっている場合と0.02秒程度(これが通常)の場合が同じサーバで発生していることが判明。
この違いをもとにい調べたところどうもPOSTするデータのサイズの違いではないかと気づいた。
そこでPOSTデータサイズを変えながら検証すると、1023バイトまでは遅延なしで1024バイト以上になると遅延が発生することがわかった。
しかし、さらに検証を続けているうちに1024バイト以上のPOSTデータでも遅延が発生しない場合があることが判明。
どうやらApacheに直接送信すると問題が発生しないっぽい。その環境の違いが間にPoundを挟むかどうかの違いだったというわけ。
スクリプト側での対策
というわけで、Poundとcurl7.13以降の組み合わせによって発生するものだとわかったので、「curl 1024バイト」をキーワードに調べてみた。
その結果以下のページに行き着く。
これによるとcurlでは1024バイト以上のデータを送信する場合に「Expect: 100-continue」ヘッダを自動で付与するらしい(ただしこれはcurl-7.13以降の場合)*1。
tcpdumpでパケットを覗くとなるほどたしかに1024バイト以上のときのみヘッダを付与している。
上記のサイトによると対策としては「Expect: 100-continue」を送信しないようにcurl_setoptでExpectヘッダを抑制すればよいとのこと。このケースではwebサーバが417ヘッダを返してきたときの対応の流れであって、今回のと同じではないがためしにcurlのセットのところで以下の行を追加した。
curl_setopt($ch, CURLOPT_HTTPHEADER, array('Expect:'));
これで実行したところ遅延が解消された！
しかし、謎が深まるのはここからだった・・・。
悪いのはExpectヘッダではない
curlが勝手に「Expect: 100-continue」をつけるってのはHTTPのRFCの仕様としては正しいものである。
で、今回は上記のTwitterのケースのように417で対応不可を返答してきているわけではない。なぜならPoundを経由させないでwebサーバー(Apache)に向けてExpectヘッダを抑制せずに直接リクエストを送信したら、「HTTP/1.1 100 Continue」が返ってくるからだ。
本来の流れとしては
- curlが「Expect: 100-continue」を含めたヘッダを投げる
- 受け取ったwebサーバが「HTTP/1.1 100 Continue」を返す
- それを確認したcurlがデータ送信OKの確認がとれたのでデータのPOSTを開始する
なんだけど、問題なのはこのヘッダを受け取ったときのPoundの挙動とそれに対するcurlの挙動のようである(curlの場合は正常な動作なんだけど)。
そこでソースを眺めていると関係しているっぽい箇所を見つけた。
- curl-7.15.5/lib/urldata.h
bool write_after_100_header; /* TRUE = we enable the write after we received a 100-continue/timeout or FALSE = directly */ bool wait100_after_headers; /* TRUE = after the request-headers have been sent off properly, we go into the wait100 state, FALSE = don't */
- curl-7.15.5/lib/transfer.c
#define CURL_TIMEOUT_EXPECT_100 1000 /* counting ms here */
このtransfer.cで100のヘッダの挙動を見て時間を計ってるような感じ。
推測するに、
- 明示的に抑制しない場合、1024バイト以上のデータ送信時にcurlが自動で「Expect: 100-continue」を付与する。
- HTTPサーバ(Apache)に直接送出した場合は、「HTTP/1.1 100 Continue」が返されるので即座にデータの送信が始まる
- Poundを経由した場合、Poundはこのヘッダを受け取ってもHTTPサーバへ中継せず、クライアントへレスポンスも返さないのでcurlはtimeoutするまで処理を遅延させる(約2秒)。
- timeout後送信を開始する
どうもこんな感じな気がする。
気がするというのはソースを追っかけたが残念ながらよくわからなかったからだ。Cがよくわかりません・・・。
なんで2秒になるのかもよくわからなかった。
ちなみに明示的に「Expect: 100-continue」を付与した場合も「Expect」を抑制したときと同じようにtimeoutは発生しなかった。
なので、curlが自分で付与した場合のみの挙動と思われる。
Poundの挙動
Poundの挙動を調べているうちに別のエントリも見つけた。
Poundが不正なリクエストを自動で破棄するらしい。「不正なリクエスト」扱いされたのが原因なのかなー。
- Pound-2.4.5/svc.c
check_header(const char *header, char *const content) { regmatch_t matches[4]; static struct { char header[32]; int len; int val; } hd_types[] = { { "Transfer-encoding", 17, HEADER_TRANSFER_ENCODING }, { "Content-length", 14, HEADER_CONTENT_LENGTH }, { "Connection", 10, HEADER_CONNECTION }, { "Location", 8, HEADER_LOCATION }, { "Content-location", 16, HEADER_CONTLOCATION }, { "Host", 4, HEADER_HOST }, { "Referer", 7, HEADER_REFERER }, { "User-agent", 10, HEADER_USER_AGENT }, { "Destination", 11, HEADER_DESTINATION }, { "", 0, HEADER_OTHER }, }; int i; if(!regexec(&HEADER, header, 4, matches, 0)) { for(i = 0; hd_types[i].len > 0; i++) if((matches[1].rm_eo - matches[1].rm_so) == hd_types[i].len && strncasecmp(header + matches[1].rm_so, hd_types[i].header, hd_types[i].len) == 0) { /* we know that the original header was read into a buffer of size MAXBUF, so no overflow */ strncpy(content, header + matches[2].rm_so, matches[2].rm_eo - matches[2].rm_so); content[matches[2].rm_eo - matches[2].rm_so] = '\0'; return hd_types[i].val; } return HEADER_OTHER; } else if(header[0] == ' ' || header[0] == '\t') { *content = '\0'; return HEADER_OTHER; } else return HEADER_ILLEGAL; }
ここで定義されていないからHEADER_OTHERが返されて、http.cでのヘッダ判定でスルーされたままレスポンスがないという流れ？
試しに
curl_setopt($ch, CURLOPT_HTTPHEADER, array('hoge: foo'));
とかつけても同じようにタイムアウト(2秒)まで処理待ちになった。
ちなみに以下の様なPEARのHTTP:Clientを使ったスクリプトだと、変なヘッダ付けたりExpectつけたりしても処理待ちは発生しない。
なぜならにいきなりデータを送りつけるから。
<?php require_once('HTTP/Client.php'); $data = "a"; for ($i = 1; $i < 1019; $i++) { $data .= "a"; } $params = array("data" => $data); $url = "http://127.0.0.1:8080/hoge.php"; $client =& new HTTP_Client(); $client->setDefaultHeader('hogehoge', 'aaaaaaa'); $client->setDefaultHeader('Expect', '100-continue'); $client->post($url, $params);
結論
ごちゃごちゃ書いてよくわからなくなったのでまとめ。
curlでのデータ送信時、送信先のバランサがPoundを使っていて尚且つ1024バイト以上のデータを送る可能性がある場合はcurl_setopt()で「Expect: 100-continue」を抑止しておく。
自社内でわかってるならつけなくてもいいかもしれないが、外部APIを利用する場合にはまる可能性がある。
単発のPOSTなら気にしなくてもいいけど、今回はループでこの処理を回していたので遅延が命取りになった。
時間がなかったのでこれ以上追えなかったけど(ここまでで2日以上かかった)、回避策としてはヘッダの抑制というのがわかったのでこれでとりあえず良しとしよう。
もっと詳しくわかる方いれば是非教えてくださいm(_ _)m
その他参考ページ
*1:HTTPの100 ContinueヘッダについてはStudying HTTP HTTP Status Codeを参照
