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

[DeleGate-En] Re: Timeout issues
30 Jan 2006 07:59:39 GMT Gertjan Klein <peugabdyi-g7ilkru7mhjr.ml@ml.delegate.org>


Yutaka,

First of all, thanks for your help.

>You can inspect the resolver problem by getting detailed log of it with
>RES_DEBUG=1 option.

I had RES_DEBUG=9 as commandline option. I've changed it to 1 as you
suggested, which appears to result in less messages.

>The problem can be solved by supressing the DeleGate's
>original resolver (Resolvy) and using the standard resolver of Windows
>only by specifying a parameter as this:
>
>  RESOLV=sys

I have tried this, but unfortunately the problem is still there. The
full log of a test session (quoted to prevent line wrapping, note
comments inbetween):

>01/30 08:45:10.77 [2736] 0+0: PORT> -P8080
>01/30 08:45:10.77 [2736] 0+0: ## RES_ORDER=S
>(WIN) 45:10 [2736] setNonblockingSocket(8,1)=0
>01/30 08:45:10.77 [2736] 0+0: --INITIALIZATION START: 9.0.3 on WindowsNT--
>01/30 08:45:10.77 [2736] 0+0: BINSHELL=/bin/sh
>01/30 08:45:10.77 [2736] 0+0: server_open(delegate,:8080,listen=20)
>01/30 08:45:10.77 [2736] 0+0: server_open(delegate,:8080) BOUND
>01/30 08:45:10.77 [2736] 0+0: DGROOT=c:/program files/delegate^M
>01/30 08:45:10.77 [2736] 0+0: <DeleGate/9.0.3> [2736] -P8080 READY^M
><DeleGate/9.0.3> [2736] -P8080 READY
>DGROOT=c:/program files/delegate
>ADMIN=peugabdyi-g7ilkru7mhjr.ml@ml.delegate.org
>AIST-Product-ID: 2000-ETL-198715-01, H14PRO-049, H15PRO-165
>Copyright (c) 1994-2000 Yutaka Sato and ETL,AIST,MITI
>Copyright (c) 2001-2005 National Institute of Advanced Industrial Science and Technology (AIST)
>01/30 08:45:10.78 [2736] 0+0: PORT= 8080/9 (31,144)
>01/30 08:45:10.78 [2736] 0+0: OWNER=nobody => OWNER=?/?(?/?)
>01/30 08:45:10.78 [2736] 0+0: REMITTABLE = ftp-data,ftp,ftps,telnet,telnets,smtp,smtp-data,whois,domain,dns,gopher,finger,http,https
>,ssltunnel,pop,pop3s,imap,imaps,ident,nntp,nntps,news,nbt,prospero,archie,wais,tsp,ldap,ldaps,lpr,X,syslog,talk,socks,icap,cuseeme,i
>cp,http-proxy,pam,httpam,dgauth,delegate,tcprelay,udprelay,udprelay1,teleport,coupler,vsap,sockmux,thruway
>(WIN) 45:10 [2736] DLL 10000000 ssleay32.dll
>01/30 08:45:10.78 [2736] 0+0: --- [ssleay32.dll] 10000000 ssleay32.dll
>01/30 08:45:10.78 [2736] 0+0: ---- [ssleay32.dll] loaded 73 syms, unknown=26, already=0
>(WIN) 45:10 [2736] DLL 1020000 libeay32.dll
>01/30 08:45:10.78 [2736] 0+0: --- [libeay32.dll] 1020000 libeay32.dll
>01/30 08:45:10.78 [2736] 0+0: ---- [libeay32.dll] loaded 73 syms, unknown=0, already=47
>01/30 08:45:10.78 [2736] 0+0: ---- unknown = 0, already = 47 / 73
>(WIN) 45:10 [2736] DLL 0 z
>01/30 08:45:10.78 [2736] 0+0: --- [z] 0 z
>01/30 08:45:10.78 [2736] 0+0: ## cannot load z
>01/30 08:45:10.78 [2736] 0+0: LIBPATH: gzip -> c:/program files/delegate/lib\gzip.exe
>01/30 08:45:10.78 [2736] 0+0: #### gzip = [c:/program files/delegate/lib\gzip.exe]gzip
>01/30 08:45:10.78 [2736] 0+0: #### gunzip = [c:/program files/delegate/lib\gzip.exe]gzip -d
>01/30 08:45:10.78 [2736] 0+0: ADMIN=peugabdyi-g7ilkru7mhjr.ml@ml.delegate.org protocol=http(specialist)
>01/30 08:45:10.78 [2736] 0+0: MOUNT[0]X[2] /-/builtin/icons/* = default
>01/30 08:45:10.78 [2736] 0+0: MOUNT[1]X[3] /-/* = forbidden,from=!.RELIABLE,default
>01/30 08:45:10.78 [2736] 0+0: MOUNT[2]X[0] /-* = default
>01/30 08:45:10.78 [2736] 0+0: MOUNT[3]X[1] /=* = default
>01/30 08:45:10.78 [2736] 0+0: MOUNT[4]=[4] /favicon.ico builtin:icons/ysato/default.ico default,direction=fo,onerror=404,expires=15m
>
>01/30 08:45:10.78 [2736] 0+0: #### stack size limit = FFFFFFFF (-1)
>01/30 08:45:10.78 [2736] 0+0: Stay open PIDFILE for accept() lock[fd=11]
>01/30 08:45:10.78 [2736] 0+0: env[33] LIBPATH=.;C:\Program Files\DeleGate;c:/program files/delegate/lib;.;c:/program files/delegate/
>etc
>01/30 08:45:10.78 [2736] 0+0: arg[3] RES_DEBUG=1
>01/30 08:45:10.78 [2736] 0+0: arg[4] RESOLV=sys
>01/30 08:45:10.78 [2736] 0+0: arg[5] SERVER=http
>01/30 08:45:10.78 [2736] 0+0: arg[6] FSV=sslway
>01/30 08:45:10.78 [2736] 0+0: arg[7] DGROOT=c:/program files/delegate
>01/30 08:45:10.79 [2736] 0+0: arg[8] ADMIN=peugabdyi-g7ilkru7mhjr.ml@ml.delegate.org
>01/30 08:45:10.79 [2736] 0+0: arg[9] PERMIT=*:*:*
>01/30 08:45:10.79 [2736] 0+0: arg[10] REMITTABLE=*
>01/30 08:45:10.79 [2736] 0+0: DELEGATE_Modified[0]: 43ddc384
>01/30 08:45:10.79 [2736] 0+0: --INITIALIZATION DONE: 9.0.3 on WindowsNT--
>(WIN) 45:10 [2736] setNonblockingSocket(15,1)=0
>(WIN) 45:15 [2736] spawn() = 1720 [4056], children(alive=1,total=1) 0.030s

This line (above) reflects the moment that I start my test connection.

>(WIN) 46:15 [4056] DLL 10000000 ssleay32.dll

This very next message comes a full minute later. :(  I have no clue as
to what could cause this delay. Again, when my VPN connection is not
there, the response is almost immediate.

>(WIN) 46:15 [4056] DLL 1020000 libeay32.dll
>(WIN) 46:15 [4056] DLL 0 z
>01/30 08:46:15.87 [4056] 1+1: #### countUp: nonexistent 5916, c:/program files/delegate/act/clients/20/127.0.0.1..localhost
>01/30 08:46:15.87 [4056] 1+1: (0) accepted [17] -@[127.0.0.1]localhost:3963 (60.186s)(1)
>01/30 08:46:15.88 [4056] 1+1: #HT11 Don't Keep-Alive [POST] with body: Content-Length: 532^M
>01/30 08:46:15.88 [4056] 1+1: Proxy: host=localhost; User-Agent: Mozilla/4.0 (compatible; Cache;); DIRECT
>01/30 08:46:15.88 [4056] 1+1: HCKA:[0] Close; host=localhost; (User-Agent: Mozilla/4.0 (compatible; Cache;))
>01/30 08:46:15.88 [4056] 1+1: REQUEST - POST https://213.84.105.96:443/reflector.php HTTP/1.0^M
>01/30 08:46:15.88 [4056] 1+1: connectTO: assume in non-blocking mode
>(WIN) 46:15 [4056] setNonblockingSocket(20,1)=0
>(WIN) 46:15 [4056] setNonblockingSocket(20,0)=0
>01/30 08:46:15.98 [4056] 1+1: ## connect[20] TIMEOUT(100)
>01/30 08:46:15.98 [4056] 1+1: {R} No local NS (10.1.1.109:53)
>01/30 08:46:15.99 [4056] 1+1: PATH> https://213.84.105.96:443!localhost:8080!localhost:3963!anonymous@localhost;1138607175
>01/30 08:46:15.99 [4056] 1+1: REQUEST = [https://213.84.105.96:443/] POST /reflector.php HTTP/1.0^M
>01/30 08:46:15.99 [4056] 1+1: connectTO: assume in non-blocking mode
>(WIN) 46:15 [4056] setNonblockingSocket(20,1)=0
>(WIN) 46:15 [4056] setNonblockingSocket(20,0)=0
>01/30 08:46:16.00 [4056] 1+1: ConnectToServer connected [20] {213.84.105.96:443 <- 10.1.1.109:3970} [0.010s]
>01/30 08:46:16.00 [4056] 1+1: willSTLS_SV: ServerFlags=10
>(WIN) 46:16 [4056] spawn() = 1904 [4416], children(alive=1,total=1) 0.021s
>01/30 08:46:16.02 [4056] 1+1: HTTP => (213.84.105.96:443) POST /reflector.php HTTP/1.0^M
>01/30 08:46:16.02 [4056] 1+1: relayRequestBody1 done (532/532)
>(WIN) 48:16 [4416] DLL 10000000 ssleay32.dll
>(WIN) 48:16 [4416] DLL 1020000 libeay32.dll
>(WIN) 48:16 [4416] DLL 0 z
>01/30 08:48:16.31 [4416] 1+0: gethostbyname(-) unknown[0.00s]
>01/30 08:48:16.31 [4416] 1+0: [FSV] callFilter2: 25=1 26=1 sslway
>01/30 08:48:17.86 [4416] 1+0: ## SSLway ## 1.202000 connected/accepted
>01/30 08:48:17.86 [4416] 1+0: ## SSLway server's cert. = **subject<</CN=www.gklein.org>> **issuer<</O=Root CA/OU=http://www.cacert.o
>rg/CN=CA Cert Signing Authority/Email=support@cacert..>>
>01/30 08:48:17.94 [4056] 1+1: ClosedOnTimeout(1): time=1138607297/1138607205 ppid=2736/2736 pid=4056/4056
>01/30 08:48:17.94 [4056] 1+1: #HT11 SERVER ver[HTTP/1.1] conn[close]
>01/30 08:48:17.94 [4056] 1+1: HTTP/1.1 200 Content-{Type:text/html Encoding:[/] Leng:0} Server:Apache/1.3.26 (Unix) Debian GNU/Linux
> mod_ssl/2.8.9 OpenSSL/0.9.6c PHP/4.1.2 DAV/1.0.3
>(WIN) 48:17 [4056] send(1315) = -1+1024 errno=10053
>(WIN) 48:17 [4056] -- SOCKET send(1880/17,b38140,1315,0) = 1024 6
>(WIN) 48:17 [4056] -- SOCKET recv(20)=0 error=0 [0.000]
>(WIN) 48:17 [4056] send(26) = -1+0 errno=10053
>(WIN) 48:17 [4056] -- SOCKET send(1880/17,b38140,26,0) = -1 6
>01/30 08:48:17.94 [4056] 1+1: HTTP transmitted: 241head+1057/0body=>0txt+0bin->1057/0, 8i/2o/0f/0.0
>(WIN) 48:17 [4056] -- SOCKET recv(20)=0 error=0 [0.000]
>01/30 08:48:17.94 [4056] 1+1: #HT11 EOF from the server
>01/30 08:48:17.94 [4056] 1+1: #HT11 close svsokcs[24,25]
>01/30 08:48:17.95 [4056] 1+1: disconnected [17] -@[127.0.0.1]localhost:3963 (182.262s)(0)
>(WIN) 48:17 [4056] wait3(N) = 1904 [4416] 0, children(alive=0,total=1) 0.00s
>01/30 08:48:17.95 [4056] 1+1: CFI process [1904] done (1/1 AFT-0)
>localhost - - [30/Jan/2006:08:48:17 +0100] "POST https://213.84.105.96/reflector.php HTTP/1.0" 200 1057 0*0.031+121.915:W:0-
>01/30 08:48:17.95 [4056] 1+1: StickyServer done [nonStickyProtocol(http:https:https)] 1 req / 1 conn / 122 sec
>(WIN) 48:30 [2736] wait3(N) = 1720 [4056] 0, children(alive=0,total=1) 0.00s

As you can see, after the minute's wait everything then continues
normally, i.e. the connection to the server is made and a response is
returned.

I hope you can give me some clues as to what I might try next.

Thanks in advance,
Gertjan.

-- 
Gertjan Klein <peugabdyi-g7ilkru7mhjr.ml@ml.delegate.org>

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