CurlORBでのエラー？？

[kim]

とても興味深く拝見しました。

「Curlからのデータがサーバに到達していない。」
ということですので、問題は
　クライアント（Curl）、ネットワーク、サーバ
の何れかにありますね。

３つのどこに問題がありそうか アタリ をつけるために、
クライアントとサーバ側にパケットキャプチャをしこんで確認するのがよいと思います。


●クライアント側にパケットキャプチャをインストールして
　　・Curlのコードで書かれたデータがパケットキャプチャにて
　　　HTTPリクエストとして 正しく出力されているか
　を確認する。

●サーバ側にパケットキャプチャをインストールして
　　・Curlのコードで書かれたデータがサーバ側に到達しているか
　　　パケットキャプチャにて確認する


「クライアントからのHTTPリクエストが正しく、サーバ側でデータが到達していない。」
というのであれば、ネットワークかサーバ側に問題があると思いますので、
サーバ側のAPサーバをtomcatなどに変更してエラーが出るか確認するのも有効かと思います。

[okm]

kimさま

ありがとうございます。

クライアント側のキャプチャですが、HTTPで送信できていないような気がします・・。
※キャプチャソフトの見方を理解し切れておらず、はっきり言えずすみません。

Frame# Time ort ort Info
33339 11:27:30.216 :1811 -> :80 SYN
:
33347 11:27:30.222 :1811 -> :80 POST /SMAP_UI/new-instance HTTP/1.1
33348 11:27:30.228 :1811 <- :80 ACK for #33347

(300秒) POST dataは送っていません

150545 11:32:30.464 :1811 <- :80 HTTP/1.1 200 OK
:


サーバー側にキャプチャは仕込んでないのですが、HTTPサーバのアクセスログはバイト数なしでした。

access.logにも受け取ったbyte数が表示されていません。※下記赤字部分
-----
128.1.1.XXX - - [17/Oct/2012:11:25:23 +0900]
"POST /SMAP_UI/destroy-instance HTTP/1.1" 200 64
128.1.1.48 - - [17/Oct/2012:11:24:56 +0900] "POST /SMAP_UI/new-instance
HTTP/1.1" 200 -
128.1.1.XXX - - [17/Oct/2012:11:30:40 +0900]
"POST /SMAP_UI/acKeepSession.do HTTP/1.1" 200 74
-----


CurlからHTTPで送られていない、なんてことも考えられるのでしょうか？

[kim]

33347 11:27:30.222 :1811 -> :80 POST /SMAP_UI/new-instance HTTP/1.1
の行にてクライアントからサーバにリクエストを出していて その結果として、サーバより
　150545 11:32:30.464 :1811 <- :80 HTTP/1.1 200 OK
が返却されているのでクライアントのログからはサーバも「正常」と処理しているように見えますね。

クライアントからの送信は正しいように見えますので、ネットワークかサーバを調べてみたほうがよさそうですね。

[okm]

kimさま

ありがとうございます。

すみません、
　150545 11:32:30.464 :1811 <- :80 HTTP/1.1 200 OK

この200 OK は、HTTPサーバのバグでして、本来は400を返さなければならないものなんです。

うちがFixPackをあててないんです・・。

200が返ってきてるんですが、中身は400でして、
Curlは正常データが戻ってきたと思って普通に読み込もうとして、 EndOfStreamException が発生してしまいます。

[kim]

うちがFixPackをあててないんです・・。

200が返ってきてるんですが、中身は400でして、
Curlは正常データが戻ってきたと思って普通に読み込もうとして、 EndOfStreamException が発生してしまいます。

サーバのバグとのことなんですね。　Curl側では　200のつもりで処理しているわけですからサーバを正しく直せば解決できそうですね。

サーバのアクセスログでサイズが-となっているのもバグが影響してそうですね。

[okm]

kimさま

うーん、アクセスログのサイズ-までがバグという認識はありませんでした。
サーバー側のサポートもサイズは信用しているようでした・・。

このFixPackをあてて、200を400にしたところで、結局Curlのエラーになると思います。
問題は、Curlがデータをきちんと送れていないのではないか、と疑問があがっていることです。
データをきちんと送れていれば、サーバが200を返しても問題はないはずですからね・・。

Curlがデータを送れているのか疑問にあがっているのは、サーバのサポートセンターから以下のように言われたからです。

「クライアントのIPトレースを確認したところ、クライアント側からデータを送付していないことが確認できました。」
2つ前の投稿のクライアントのIPトレースがそれなんですが、こうはっきり言われましたら疑ってしまいますよね。

クライアントの問題なのか、ネットワークの問題なのか、いまいちハッキリできておりません！
はやくスッキリしたいです！

[nasuB]

久しぶりに来てみたら、めっちゃ長いコメント・・・。
この「本当は400で返す」とか「FixPack」って何のこっちゃわからないが、最初にIBMのエラーが発生していたということから、WebSphereを使っているっぽいけど、そもそも、このエラーが発生しているということはサーバに何らかは到達してるのでは？このエラーの原因はよく分からないけど、例えばサーバが問題か否かは、Tomcatなどにスイッチして同様の問題が発生するか調べてみたらどうだろう。（もしくはパッチはあててみて試したのかな。）
クライアントからACKを返しているところからコネクションは張れているようで、CurlではHTTP通信でWinInetを使っているようで（以下参照）、WinInetをデバッグしてみたらどうだろう。
http://developers.curlap.com/faq/49-faq-...llapi.html
http://d.hatena.ne.jp/pekeq/20050325/p2

また、ネットワーク的にもVPN、プロキシー、バランサー、スイッチなどなど含めクライアントーサーバ間のどこまで到達してるかどうかを総合的に確認することで、問題は発見できる可能性があると思う。
この手の問題は、手当たり次第メーカに聞いても、どうせ自分たちの環境／構成をわかっている訳ではないので、それぞれの範囲でしか回答してくれず、たらい回しにされるだろうから、アプリ、インフラ、ネットワークを現在総合的に見ている保守担当者によって手順を踏んで問題切り分けしないとなかなか解決に至らないと思いナス。
-B

[okm]

nasuBさん

アドバイスありがとうございます。そうですよね、すごい量・・。また大量に書くけど･･。

流れを整理すると・・
ユーザーから以下のような報告があり「仕事にならない！」と怒られました。
検索ボタン押下
　↓↓
300秒待機
　↓↓
Curlアプレット例外発生！（EndOfStreamException）

そこでまず最初のSyslogを発生時間から突き止め、Curl、IBMに問い合わせました。
Curl→CurlORBはオープンソースなのでSNSできいてくれ　→今に至る
IBM→再現時のログを取得してくれ

IBMの報告
・HTTPのプラグインのデフォルトTimeOutが300秒
・WASのチャネルのTimeOutが60秒
・クライアントから○○bytes送りますよ！という情報は受け取った。
　しかしその後データが送られてこず、WASのTimeOut（60秒）が発生
　　→Syslogの最初にWASが吐いているExceptionはこれ。
　クライアントのキャプチャをみても、POSTは一度きりでその後送られてきていない（CurlORBは一度のサーバーアクセスで3度POSTする）
　※ここの根拠は今まで出したとおり、クライアントのキャプチャやHTTPサーバ、プラグインのログなどから判断
・そもそもHTTPサーバにバグがあり、300秒経過してTimeOutになった際に400を返すべきだが、200OKを返してしまっている

IBMの報告を受けて、Curlの動きを推測
・データを全て送りきれていないのを感知できていないのでは？　→Curlのバグ？
・HTTPサーバが200OKを返しているのでCurl的にはOKと思っていてResponseを読み込もうとしたけど
　実際は400の内容が返ってきているので辻褄が合わずEndOfStreamExceptionが発生している　→Curlの動き的には正しい。

こちらで試したこと
・CurlORBのsend.scurlにtry～catchを仕込んで、catchされたらsend処理をもう一回
　→2度目のループで問題なく検索処理が完了した。（※画面からsend処理の間にデータがなくなったわけではない）
・プラグインTimeOutを短縮
　→検索ボタン押下から300秒待たなくなったが根本解決ではない。全然ない。

Wininetのデバッグなんぞは知りませんでした。
リンク先よくよく読んでみます。

この手の問題は、手当たり次第メーカに聞いても、どうせ自分たちの環境／構成をわかっている訳ではないので、それぞれの範囲でしか回答してくれず、たらい回しにされるだろうから、アプリ、インフラ、ネットワークを現在総合的に見ている保守担当者によって手順を踏んで問題切り分けしないとなかなか解決に至らないと思いナス。

仰るとおり！
必ず発生する事象だと総合的に確認が取れるのですが、毎回じゃないんです・・。
いつ発生するかわからないので一日中バグを仕込んでおく･･なんてことは到底出来ず。。
仕事ができないと言われていたので超急ぎ案件だったこともあり（もう1ヶ月ですが・・）、まずそれぞれのメーカーにきいて問題の切り分けないし解決したかったのです。

[nasuB]

文章長すぎてちゃんと読んでいナスですが、
問題切り分けは保守・運用者の腕の見せ所だと思います。

がんばってください。

-B

[okm]

熱意あふれすぎですみません（笑）

まとめると、
クライアントのキャプチャをみるとデータを完全にPOSTできていないので、
①Curlでsend処理時に欠損（？）しているか
②CurlからクライアントのTCPIPにのる間に欠損（？）しているか
のどちらかだと思っています！

4行になりましたｗ

①ならCurlのバグじゃないの？
②かどうかは、教えてもらったデバッグがどう試せるか・・ってとこですかね・・。