On 05/20/08(10:20) you <plmaabrv6-mxhgu42xih3w.ml@delegate.org> wrote
in <_A91@delegate-ja.ML_>
 |はじめまして。（株）日立製作所の川崎浩史と申します。
 |現在DeleGateのバージョン9.7.6を使用してキャッシュサーバを運用しております。
 |本システムは昨年5/8に(株)日立システムアンドサービスの松本大作、10/28に鈴木猛充が
 |DeleGateに関しての問い合わせを行わせて頂いた件が2008/5/7から本格的に運用を開始
 |しております。
 |さて、本日メールさせて頂きましたのは昨日(5/19）にDeleGateのキャッシュ保存領域の１
 |ファイルが破損（マスタのファイルより小さいファイルサイズになっており内容を見ると、途中
 |で切れている）している事象が発生しております。
 |また、DeleGateから出力されているログを見たところfwriteTIMEOUT()が発生しており、その
 |後にマスタのファイルサイズよりも小さいサイズでwriteされているログが残っておりました。
 |本事象に関しまして以下の点についてご教授頂ければ幸いです。
 |
 |（１）DeleGateの出力しているログの見方に関してのドキュメントは公開されていますでしょうか？

メーリングリストのほうで散発的に説明していると思いますが、特にまとめてはありません。
だいたいは見た通りでわかるものも多いと思いますし、Windows固有のものを除いてソースを
公開していますので、出力されている文字列と突き合わせればわかると思います。
実際のところ、何か未知の問題が発生した場合には、ログと突き合わせながらソースプロ
グラムを追跡して行く以外には、解決法に至るのは困難だと思います。


 |（２）本事象を回避するようなオプション又はパッチ等はありますでしょうか？

これは状況としては「応答の転送が完了する前にクライアントが切断した場合」に発生する
問題ですね。「サーバからの応答をキャッシュしつつクライアントに中継している場合」に
不完全なキャッシュが残されてしまう問題があって、これは9.8.2-pre5で直したのですが、
川崎さんご指摘の状況は「DeleGate自身のキャッシュからの転送中にクライアントが切断」
した場合です。かつ、その該当するHTTP要求において「キャッシュの更新の有無を調べる
ためにサーバに問い合わせた結果変更無しと判明した(サーバから304応答)場合、結局
DeleGate自身のキャッシュから転送することになった場合」です。この場合、LOGFILE中に
"... =+= 304 ..." と記録され、PROGOLOG中には :S: (stable)記録されます。
一方、クライアントへの転送中にコネクションが切断された場合には、書き込みの失敗/EPIPE
状態として検出され、中継処理を中途終了します。LOGFILE中に "SIGPIPE" とか
"EPIPE fwriteTIMEOUT" が記録され、PROTOLOG中には :P: (premature EOF)と記録されます。
これ自体は正常です。
問題は、キャッシュからの転送中にもかかわらず、EPIPE が発生した場合に、キャッシュを
転送完了位置まででtruncateしていることです。これは、"=+= 304" としての処理中にEPIPEが
発生した場合には、EPIPEの発生が優先され、キャッシュの現在位置でtruncateするように
なってしまっていたからです。（中継終了コードを保持する変数 httpStat を CS_STABLE == 'S'
の状態として応答の中継を開始しますが、EPIPE の発生時に CS_EOF 'P' で上書きしてしまい、
終了後 httpStat == CS_STABLE でないので、切断してしまっている。そもそもこの truncate
自体、現在の実装(9.2.4以降)では不要になっているはずのものではあるのですが...）

★修正方法★　一番簡単なのは同封のパッチのように、キャッシュの truncate を抑制する
フラグを立てることです。

なお、この問題が発生する条件は、

　・EXPIREの値が非常に短く設定され（問題となり得る状況がその値に相当する頻度で発生）
　・転送に時間がかかる状態で　（クライアントからの割り込みがかかり易い）
　・転送中にクライアントの切断された場合に発生する
　・クライアント側で(Pragma:no-cache付)強制リロードすると解消する

というレア系ものなので、これまで見逃されていたものと思います。



また、今回の件とは異なりますが、去年の12月に9.8.2-pre5で修正した問題は以下のようなもの
でした。

[CHANGES]
9.8.2 071226 fix http.c: discarding incomplete cache (truncated by client reset)

On 12/31/07(17:37) I wrote in <_A13930@delegate.ML_>
 |DeleGate/9.8.2-pre5 をアップロードしました。
 |
 |・主に Windows 特に WindowsCE 版向けの修正です。
...
 |・不完全キャッシュファイルの廃棄
 |　受信途中にクライアントから切断され、またDeleGateによる代行受信も行なわれ
 |　なかった場合に生じる不完全なキャッシュファイルを、明示的に判定して、削除
 |　するようにしました。（この問題も、WinCEでばりばり切断しまくっているうちに
 |　見つけました^^;）

この修正だけを、古い版に適用する方法はありませんが、現在の9.8.2 (現在pre34) は
すでに十分に安定な状態にあり、9.7.X までにあったバグの多くが修正されています。
正式なリリースになっていないのは、WindowsCE 固有の未完の機能が残っているからです。


 |（３）回避が困難な場合、ログを監視し本事象が発生したことを検知することを考えておりますが
 |　　DeleGateの出力しているログの内容から事象が発生したと断定できるようなキーワードはあり
 |　　ますでしょうか？
 |
 |添付ファイルに該当ファイルに関する部分のログを抜粋を送付させて頂きます。
 |今回の事象の対象ファイルは、ファイルサイズが682,307バイトとなっています。
 |添付ファイルの「20080519_8443.http抜粋」の19/May/2008:13:14:36の部分では正しいファイル
 |サイズで処理されており、19/May/2008:13:56:32の時点でファイルが破損した状態になっています。
 |それ以降破損した状態で処理が続き19/May/2008:15:23:33の時点でさらに破損しています。
 |15:30頃に破損したファイルを削除した為、19/May/2008:15:34:48から正常に戻っています。
 |また、「20080519_8443抜粋」では、05/19 13:56:32.88の下にでている(WIN) 56:32.88の行が上記
 |メールで記載しておりますfwriteTIMEOUT()の部分、05/19 13:56:32.88の行が小さいサイズでwrite
 |されていると思われる部分になります。

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


*** ../delegate9.7.8-pre1/src/http.c	Thu Mar 27 11:50:10 2008
--- src/http.c	Wed May 21 15:45:57 2008
***************
*** 4652,4657 ****
--- 4652,4659 ----
  
  			sv1log("HTTP <=+= %d [%s] %s",RespCode,RX_cpath,req);
  			httpStat = CS_STABLE;
+ 			DontTruncate = 1; /* 9.7.8 to avoid trunccation
+ 				if( httpStat == CS_STABLE ) becomes false */
  
  			if( HTTP_opts & HTTP_OLDCACHE ){
  			distFromCacheSetup(Conn,RX,RX_cpath,RX_cachefp);