On 06/03/08(14:49) you <pmmaabrv6-mxhgu475qh3w.ml@delegate.org> wrote
in <_A99@delegate-ja.ML_>
 |こんにちは。（株）日立製作所の川崎浩史です。
...
 |本日メールさせて頂いたのは、不完全なキャッシュファイル作成されるケースが再度
 |発生しております。
 |今回は前回対応頂いているケースとは異なり、DeleGateのキャッシュファイルが存在
 |しない状態でアクセスがありエラーとなった際に発生しているのではないかと思われ
 |ます。
 |DeleGateのログを見たのですが今回は、前回のように不完全な状態でWriteしたような
 |ログは残っておらずどの時点で不完全な状態で作成されたかが分からない状況です。
 |
 |前回のメールで記載頂いている
 ||・不完全キャッシュファイルの廃棄
 ||　受信途中にクライアントから切断され、またDeleGateによる代行受信も行なわれ
 ||　なかった場合に生じる不完全なキャッシュファイルを、明示的に判定して、削除
 ||　するようにしました。（この問題も、WinCEでばりばり切断しまくっているうちに
 ||　見つけました^^;）
 |に該当するのでしょうか？

いえ、それは、応答ヘッダにContent-Lengthが無い場合（動的に生成される応答など）
の問題でしたので、今回の件とは関係ないと思います。（そのような応答は例外的な
応答のはずですが、とある有名サイトではそれがデフォルトで）

もともと、Content-Lengthのある通常の応答であれば、実際にキャッシュファイルに
読み込んだサイズがそれを下回る場合、中継終了時にそのファイルは削除されます。
この場合、川崎さんが同封されたログ中にあるように rcode=-10002 unlink と表示
されます。

ですので、なぜ削除されなかったのか？が謎です。


 |また、9.8.2を適用することで不完全なキャッシュファイルが作成された場合（ヘッダ
 |のContent-Lengthのサイズと実ファイルのサイズが異なる）にマスタ側から取り直され
 |るのでしょうか？

9.7.8でも、といいますか太古の版から、キャッシュから中継した際にそのデータが
不完全であると判定した際に、そのファイルを削除するようになっています。なので、
一度だけ壊れた応答を返すことになります。

ただ問題として、キャッシュファイルがEXPIREを超えた際に、サーバに問い合わせて
「原本に変更無し」となった場合に、この検出と削除のメカニズムが働いていなかっ
たということに、今回気付きました。

これは次の版(9.7.8-pre3)で直します。


 |不完全なキャッシュファイルは286,160バイトで作成日時は6/2の12:49となっています。

13:49 ですね？


 |06/02 13:49:16.69 [4332] 1392+16: HTTP/1.1 200 Content-{Type:application/vnd.ms-excel Encoding:[/] Leng:2080256} Server:Microsoft-IIS/5.0
 |06/02 13:49:19.93 [4332] 1392+16: ## got SIGPIPE [1] in HTTP: binaryBody
 |06/02 13:49:19.93 [4332] 1392+16: ClientEOF: relay_response.SIGPIPE [28 28] 250000 000000 X
 |06/02 13:49:19.93 [4332] 1392+16: ## (1) SIGPIPE * 1: the recipient seems to be dead, Ctype:application/vnd.ms-excel

ここで応答中継中にクライアントからの切断が起こり、

 |06/02 13:49:22.01 [4332] 1392+16: CACHE_TAKEOVER: TIMEOUT=takeover:6

ここ(受信開始から6秒後)に、DeleGateによる代理での受信もタイムアウトして断念、

 |06/02 13:49:22.01 [4332] 1392+16: HTTP transmitted: 245head+285000/000000Fbody=>0txt+285915bin->179000/000000X, 204i/108o/0f/5.3 -----
 |06/02 13:49:22.01 [4332] 1392+16: rcode=-10002 unlink F:\CACHE/http/server01/dzdoc/%FFFFFF8F%FFFFFFA4%FFFFFF95i%FFFFFF95%FFFFFF94/%FFFFFF95%FFFFFFE5%FFFFFF8FW%FFFFFF8E%FFFFFF91%FFFFFF97%FFFFFFBF%FFFFFF83%FFFFFF89%FFFFFF83C%FFFFFF83u%FFFFFF83%FFFFFF89%FFFFFF83%FFFFFF8A/C-19-87%FFFFFF81`90.xls#LOADING (233472)

結果、コード -10002 (R_UNSATISFIED) で "unlink" (削除) するとなっています。
もし何かの理由で unlink() に失敗したとしても、もともと、受信時のファイル名は
"#LOADING" を付け足したファイル名で作成されてまして、正常に受信を完了した
場合にしか、#LOADING 部分を外して、キャッシュとして有効なファイル名には
付け替えられないのです。
ですので、上の結果が、有効なキャッシュとして残ったとすると、謎です。


ところで、13:49:16〜22にかけてこの処理が行なわれているのと並行して、直前の
13:49:20 に 206 コードで終了しているリクエストがあります。またすぐ後にも
206コードで終了しているものがあります。
これらのリクエストが、ファイルの削除やファイル名の付け替えの処理に、何らか
の形で干渉している可能性があるかも知れませんので、これらのログも見せて
いただけないでしょうか？

 |client021.domain.co.jp - - [02/Jun/2008:13:49:20 +0900] "GET http://server01/dzdoc/商品部/募集資料ライブラリ/C-19-87〜90.xls HTTP/1.0" 206 4145 0*0.031+0.266:RP:0+
 |client021.domain.co.jp - - [02/Jun/2008:13:49:22 +0900] "GET http://server01/dzdoc/商品部/募集資料ライブラリ/C-19-87〜90.xls HTTP/1.0" 200 285915 0*0.031+5.360:P:0H
 |client021.domain.co.jp - - [02/Jun/2008:13:49:37 +0900] "GET http://server01/dzdoc/商品部/募集資料ライブラリ/C-19-87〜90.xls HTTP/1.0" 206 913725 0*0.031+13.735:RP:0+


また、ログを長めていますと、その他にも問題があります。
・MSIEが、ナマのShift_JISのURLを送って来ている
　これはHTTPの規格上は不正なはずですが、まあ仕方ないですね。
・DeleGateがその中のMSBの立ったバイトを	%XX とすべきところを %FFFFFFXX と
　してしまっている(これも9.7.8-pre3で直します)


なお、この問題は、「切断されたキャッシュファイルを作ってしまった場合」にどう
対処するかということですが、そもそも、切断されないようにできるなら、そうした
ほうがよいと思います。例えば、

  TIMEOUT=takeover:120

とかすれば、キャッシュの作成・更新の切っ掛けとなったクライアントが中途切断
しても、DeleGateは受信とキャッシュを120秒間継続します。上のケースでは 6秒
間で200K余り受信していますから、2分あれば全体を受信できるでしょう。
もともとこのパラメタは、低速で高価な回線の利用者から、「クライアントが切断
してもDeleGateが回線を解放しない。なんとかしろ」という要求に答えて
DeleGate/5.9.2(1999年3月)で導入したものですが、そもそもそれ以前はタイム
アウト無し、だったのです。昨今のように常時接続回線が普通な状況では、もっと
デフォルトを長くしても構わないと思っています。

　　　　　　　 　　　        9 9　　
┌─┐┬┌──┬┐ ／／\^^ ( e ); {Do the more with the less -- B. Fuller}
├─┤│└─┐│ ／　877m\_<   >_ <URL:http://www.delegate.org/delegate/>
┴　└┴──┘┴──────────────────────────────
佐藤豊＠情報技術研究部門.産業技術総合研究所(独立行政法人)