Article delegate-ja/502 of [1-661] on the server localhost:119
  upper oldest olders older1 this newer1 newers latest
search
[Top/Up] [oldest] - [Older+chunk] - [Newer+chunk] - [newest + Check]
[Reference:<_A500@delegate-ja.ML_>]
Newsgroups: mail-lists.delegate-ja

[DeleGate-Ja] Re: FTPS(FTPES)でファイルがアップロードできない場合がある
07 Nov 2010 01:53:33 GMT ysato@delegate.org (Yutaka Sato)
The DeleGate Project


In message <_A500@delegate-ja.ML_> on 11/04/10(21:42:08)
you sf02 <p6aaqbrv6-7pld3vsc4trr.ml@ml.delegate.org> wrote:
 |中野です。
...
 |早速テストした結果をご報告いたします。

ありがとうございます。
症状を再現する方法と、根本問題と、その解決法がわかりましたので、
最期に修正のためのパッチを同封します。

 |前回説明不足でした動作環境は下記の通りです。
 |
 | DeleGateのホスト:Linux + DeleGate 9.9.7
 | FTPSクライアント:WindowsXP + FileZilla 3.3.4.1
 | FTPSサーバー:Linux + ProFTPD 1.3.2
...
 |---------------------------------------------------------------------
 |ログについて
 |---------------------------------------------------------------------
 |アップロードに失敗したファイル FILE000.TXT のログを抽出してみました。
 |
 |佐藤様の例と違い、なぜかスレッドが別プロセスIDになっている為、
 |FILE000.TXTのアップロード処理のみのログがどれだか判別できません
 |でしたので、初めと終わりを特定して、その間のログは削っていません。

Linuxの中には、スレッドライブラリ(pthread)としてLinuxThraedsと言う、
やや古めの?実装を提供しているものがありまして、それはスレッドを
プロセスの延長として実現しているらしく、同一プロセス内にあって空間を
共有するスレッドでありながら、互いに異なるgetpid()を見るという状況が
発生します。psなどで見ても、複数のプロセスがあるように見えます。

これは、fork()後にプロセス固有のキャッシュを持つような処理をあちこちで
行っているDeleGateにおいては問題があり、実際のユニークなプロセスIDを
識別するような uGetpid() というような関数を作ったりして使用している
のですが、該当する箇所全体に適用が済んでいない状況です。
ただ今回の問題に関しては、このとが原因ではありませんでした。
-dt のログに関しては、そのような問題の状況を意図的に示すために、生の
getpid()の結果を示すようになっています。

さて、今回の問題の根源は DeleGate が自身のSSLフィルター (SSLway)を実行
する方法として、当初はプロセスを用いていて、現在はスレッドで実現して
いるという移行の過程で生じています。フィルターとの同期をパイプで行って
いるのですが、以前はDeleGateとは別プロセスで、ファイルディスクリプタ
の空間も別だった時の実装の名残が、現在も残っています。このため、
DeleGate本体の(FTPやHTTPなどの)スレッドと、SSLway のスレッドの間での、
ディスクリプタのopen/closeがバッティングする危険が生じました。

今回の問題は、特殊な状況において、実際にそれが生じたものです。
特殊な状況と言いますのはざっくり言いますと、
・スレッドの生成に時間がかかる (数十ミリ秒以上とか)
・FTPによるデータのアップロードを行っている
・データコネクションをサーバ/クライアント向けともにSSLで暗号化している
ということです。

送っていただいたログをみましても、問題の症状が生じた場合にはスレッドの
起動に時間がかかっている様子が見られます。
中野さんのケースでスレッドの生成が遅いのは、実際に負荷が高いせいなのか、
LinuxThreadsのせいなのか、スレッドの間の実行の優先制御によるのか、
わかりませんが、たぶんそのいずれかか、組合せと思われます。

さて、同封したパッチは、その状況を強制的に再現するために挿入した遅延と、
それが生じた際に問題を起こしていたコードを修正するものです。
根本的な問題は、DeleGate本体側がSSLフィルターとの同期用のパイプを閉じた
後も、SSLフィルター側はそのファイルディスクリプタを覚えていて、それに
対して書き込みを行った結果、同期が壊れた(FSVの同期のつもりがFCLの
同期になってしまった)、その結果、FCLのデータ中継用のソケットのディスク
リプタの受渡しが壊れ、データが中継できなかった、というものです。

パッチの実体は、src/filter.c (DeleGate本体側)の clearSSLready() の
呼び出しと、filters/sslway.c (SSLフィルター側) の clearSSLready() の
定義です。

src/filter.c のパッチには、テストのために状況を再現するための、
マクロ定義を残してあります。
 #define ENBUG_HEAVYLOAD /* emulate heavy load or slow thread creation */
・これを有効にすると(高負荷等で)スレッドの生成に時間がかかる状況を再現します
 #define ENBUG_DANGLINGFD /* emulate a bug in versions older than 9.9.8 */
・これを有効にすると、9.9.8-pre18 で行った対処法を無効にします
この両者を有効にすると、問題が100%再現します。
後者だけ無効にすると、高い負荷の下でも問題が回避されることが確認できます。

パッチ済みの9.9.8-pre18も、近いうちにアップロードします。
ご協力ありがとうございました。

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

*** ../delegate9.9.8-pre17/filters/sslway.c	Tue Jun 29 12:29:50 2010
--- ./filters/sslway.c	Sun Nov  7 09:41:32 2010
***************
*** 2242,2247 ****
--- 2242,2259 ----
  
  int SSLstart = 0;
  int SSLready = -1;
+ int clearSSLready(int fd){
+ 	int nf = 0;
+ 	if( fd == cl_Ready ){
+ 		cl_Ready = -1;
+ 		nf |= 1;
+ 	}
+ 	if( fd == sv_Ready ){
+ 		sv_Ready = -1;
+ 		nf |= 2;
+ 	}
+ 	return nf;
+ }
  static void syncReady(SSLwayCTX *Sc,PCStr(sync),int do_acc,int do_con){
  	int sv,cl;
  	int wcc;
*** ../delegate9.9.8-pre17/src/filter.c	Sat Oct  9 19:15:56 2010
--- ./src/filter.c	Sun Nov  7 10:00:31 2010
***************
*** 26,31 ****
--- 26,36 ----
  History:
  	970814	extracted from service.c and delegated.c
  //////////////////////////////////////////////////////////////////////#*/
+ 
+ //#define ENBUG_HEAVYLOAD /* emulate heavy load or slow thread creation */
+ //#define ENBUG_DANGLINGFD /* emulate a bug in versions older than 9.9.8 */
+ int clearSSLready(int fd);
+ 
  #include "file.h" /* 9.9.7 should be included first with -DSTAT64 */
  #include "delegate.h"
  #include "fpoll.h"
***************
*** 2264,2269 ****
--- 2269,2277 ----
  static int threadSSLwayX(SSLwayCTX *Swc,PCStr(what),int clsock,int svsock,PCStr(filter),Connection *Conn){
  	int rc;
  
+ #if defined(ENBUG_HEAVYLOAD)
+ 	msleep(300);
+ #endif
  	Verbose("---tSSLway %8X%s base=%X %d/%d\n",getthreadid(),
  		ismainthread()?"":"S",p2i(&what),actthreads(),numthreads());
  	if( lTHREADLOG() ){
***************
*** 2421,2426 ****
--- 2429,2437 ----
  
  			SSLready = -1;
  			Swc->ss_ready = -2;
+ #if !defined(ENBUG_DANGLINGFD)
+ 			clearSSLready(sv[1]); /* 9.9.8 dangling cl/sv_Ready */
+ #endif
  			close(sv[0]);
  			close(sv[1]);
  			if( envput ){

  admin search upper oldest olders older1 this newer1 newers latest
[Top/Up] [oldest] - [Older+chunk] - [Newer+chunk] - [newest + Check]
@_@V