Article delegate-en/3711 (07Apr18) Re: Questions about SSLway

Article delegate-en/3711 of [1-5169] on the server localhost:119
[Top/Up] [oldest] - [Older+chunk] - [Newer+chunk] - [newest + Check]
[Reference:<_A3710@delegate-en.ML_>]
Newsgroups: mail-lists.delegate-en
[DeleGate-En] Re: Questions about SSLway
18 Apr 2007 08:40:30 GMT "Kwis Angelo" <phyhabdyi-6rjyzcltgs3r.ml@ml.delegate.org>

Hi Yutaka,

I have the logs below after disabling session cache and allowing the
negotiation phase logging.  I tried several times.  The first one
(highlighted in blue) was able to do establish a session.  Not long after, I
did 3 consecutive tests (highlighted in red) and all encountered the the
same error.

After 3 consecutive errors, all subsequent tests finally worked without even
restarting Delegate...what do you think is the problem?

The process was now started with the following command:

./delegated -v -P$DELEDATE_LISTNER_PORT SERVER=http FSV="sslway -ssl2 -Vrfy
-CAfile pems/TrivnetCA.crt -cert pems/ggs-delegate.crt -key pems/ggs-
delegate.key -pass pass:1234 " MOUNT="/* $HTTPS_HOST_URL/*" TLSCONF="-vd,
scache:no" RES_WAIT=0 DGROOT=/opt/gemalto/delegate951  >
 /opt/gemalto/delegate951/log/delegate.txt 2>&1 &

==================================================================

04/18 15:05:10.30 [6087] 0+0: -- setCredhyCache /tmp/credhy_cache128 >>
/opt/gemalto/delegate951/act/credhy_cache128
04/18 15:05:10.30 [6087] 0+0: command PATH:
/opt/gemalto/delegate951/src/./delegated ->
/opt/gemalto/delegate951/src/./delega
ted
04/18 15:05:10.30 [6087] 0+0: PORT> -P8077
04/18 15:05:10.31 [6087] 0+0: ... gethostname(OTA)
04/18 15:05:10.31 [6087] 0+0: configuring default RESOLV ...
04/18 15:05:10.31 [6087] 0+0: ... gethostname()='OTA'
04/18 15:05:10.31 [6087] 0+0: ... SYS: OTA -> 192.168.11.136
04/18 15:05:10.31 [6087] 0+0: ## connect[5] refused (146)
04/18 15:05:10.31 [6087] 0+0: {R} No local NS (192.168.11.136:53)
04/18 15:05:10.31 [6087] 0+0: ... NIS not available (no default domain)
04/18 15:05:10.31 [6087] 0+0: ... export RES_ORDER=CFDS
04/18 15:05:10.31 [6087] 0+0: export RESOLV=cache,file,dns,sys (set by
default)
SRCSIGN=9.5.1:20070305034311+0900:3b9b14c5e1e34f38:Author@DeleGate.ORG
:lmz3FazLKFvmy5I9SvilekIgHFCFOjVhXlNAdsY2d3rgRR5l4ZHiJT
AFWW9eUgPd0ta2jNNoWNum9o7hzQl/C9dE+uQ2DfxUUhjba5c/vG9iGxGUhV7at+fnaCiZjhZBUdiYBTAQO7jQPz8pBSSy0WE+DLETEbqFIC35jDK6Xc4=^M
BLDSIGN=9.5.1:20070321152701+0700:3b9b14c5e1e34f38:support@gemalto..:-^M
04/18 15:05:10.31 [6087] 0+0: --INITIALIZATION START-07041815+0700: 9.5.1 on
SunOS/5.9--
04/18 15:05:10.31 [6087] 0+0: EXECDIR=/opt/gemalto/delegate951/src/.
04/18 15:05:10.31 [6087] 0+0: BINSHELL=/bin/sh
04/18 15:05:10.31 [6087] 0+0: server_open(delegate,:8077,listen=20)
04/18 15:05:10.31 [6087] 0+0: server_open(delegate,:8077) BOUND
04/18 15:05:10.31 [6087] 0+0: DGROOT=/opt/gemalto/delegate951^M
04/18 15:05:10.31 [6087] 0+0: <DeleGate/9.5.1> [6087] -P8077 READY^M
04/18 15:05:10.31 [6087] 0+0: PORT= 8077/9 (31,141)
04/18 15:05:10.32 [6087] 0+0: OWNER=nobody => OWNER=gemuser/dba(gemuser/dba)
04/18 15:05:10.32 [6087] 0+0: REMITTABLE =
http,https/{80,443},gopher,ftp,wais
04/18 15:05:10.32 [6087] 0+0: --- [ssl] 0 dglibssl.so
04/18 15:05:10.32 [6087] 0+0: --- [ssl] FF340C78 libssl.so.0.9.8
04/18 15:05:10.32 [6087] 0+0: ---- [ssl] loaded 92 syms, unknown=0+0,
already=0
04/18 15:05:10.32 [6087] 0+0: +++ loaded OpenSSL 0.9.8e 23 Feb 2007
04/18 15:05:10.32 [6087] 0+0: --- [z] 0 dglibz.so
04/18 15:05:10.32 [6087] 0+0: --- [z] 0 libz.so.0.9.8
04/18 15:05:10.32 [6087] 0+0: --- [/usr/lib/libz.so]
04/18 15:05:10.32 [6087] 0+0: --- [z] FF341798 /usr/lib/libz.so
04/18 15:05:10.32 [6087] 0+0: ---- [z] loaded 9 syms, unknown=0+0, already=0
04/18 15:05:10.32 [6087] 0+0: +++ loaded Zlib 1.1.4
04/18 15:05:10.32 [6087] 0+0: #### gzip/gunzip = dynamically linked
04/18 15:05:10.33 [6087] 0+0: {R} retrying AAAA [update.microsoft.com]
04/18 15:05:10.33 [6087] 0+0: gethostbyname(update.microsoft.com) unknown[
0.00s]
04/18 15:05:10.33 [6087] 0+0: ERROR CMAP/DST[1] update.microsoft.com ?
unknown
04/18 15:05:10.33 [6087] 0+0: ADMIN=support@gemalto.comprotocol=http(specialist)
04/18 15:05:10.33 [6087] 0+0: #### CACHE DISABLED #### Cache directory seems
not exist: /opt/gemalto/delegate951/cache
04/18 15:05:10.33 [6087] 0+0: MOUNT[0]X[3] /-/builtin/icons/* = default
04/18 15:05:10.33 [6087] 0+0: MOUNT[1]X[4] /-/* =
forbidden,from=!.RELIABLE,default
04/18 15:05:10.33 [6087] 0+0: MOUNT[2]X[0] /-* = default
04/18 15:05:10.33 [6087] 0+0: MOUNT[3]X[1] /=* = default
04/18 15:05:10.33 [6087] 0+0: MOUNT[4]X[5] /favicon.ico
builtin:icons/ysato/default.ico default,direction=fo,onerror=404,expi
res=15m
04/18 15:05:10.33 [6087] 0+0: MOUNT[5]X[2] /*
https://winapi.wireless.co.id/*
04/18 15:05:10.33 [6087] 0+0: #### stack size limit = 800000 (000000X)
04/18 15:05:10.33 [6087] 0+0: Stay open PIDFILE for accept() lock[fd=11]
04/18 15:05:10.33 [6087] 0+0: StickyReport[14,13]127.0.0.127:65535><
0.0.0.0:0
04/18 15:05:10.33 [6087] 0+0: env[26]
LIBPATH=.;/opt/gemalto/delegate951/src;/opt/gemalto/delegate951/lib;/opt/gemalto/delega
te951/src/.;/opt/gemalto/delegate951/etc
04/18 15:05:10.33 [6087] 0+0: env[28] RESOLV=cache,file,dns,sys
04/18 15:05:10.33 [6087] 0+0: arg[3] SERVER=http
04/18 15:05:10.33 [6087] 0+0: arg[4] FSV=sslway -ssl2 -Vrfy -CAfile
pems/TrivnetCA.crt -cert pems/ggs-delegate.crt -key pems/
ggs-delegate.key -pass pass:1234
04/18 15:05:10.33 [6087] 0+0: arg[5] MOUNT=/*
https://winapi.wireless.co.id/*
04/18 15:05:10.33 [6087] 0+0: arg[6] TLSCONF=-vd, scache:no
04/18 15:05:10.33 [6087] 0+0: arg[7] RES_WAIT=0
04/18 15:05:10.33 [6087] 0+0: arg[8] DGROOT=/opt/gemalto/delegate951
04/18 15:05:10.33 [6087] 0+0: DELEGATE_Modified[1]: 4625d136 000000000X
04/18 15:05:10.33 [6087] 0+0: --INITIALIZATION DONE-07041815+0700: 9.5.1 on
SunOS/5.9--
04/18 15:05:10.33 [6087] 0+0: #### restarting is set on config err.
-- {{ ---- ERROR in initialization ----
ppid=1
05:10.302 [6087] delegated.c:5292 --- DO_STARTUP
05:10.302 [6087] delegated.c:5318 --- DO_INITIALIZE
05:10.302 [6087] delegated.c:5660 --- _main START
05:10.302 [6087] filter.c:414 --- [-1] command PATH:
/opt/gemalto/delegate951/src/./delegated -> /opt/gemalto/delegate951/src
/./delegated
05:10.303 [6087] delegated.c:5744 --- _main ConnInit() DONE
05:10.303 [6087] delegated.c:5751 --- _main fromInetd()=0
05:10.304 [6087] filter.c:414 --- [2] command PATH:
/opt/gemalto/delegate951/src/./delegated -> /opt/gemalto/delegate951/src/
./delegated
05:10.305 [6087] delegated.c:3134 --- _main scan_HOSTS0() DONE
05:10.305 [6087] delegated.c:3139 --- _main scan_HOSTSLISTS() DONE
05:10.308 [6087] inets.c:3869 --- export RES_ORDER=CFDS
05:10.308 [6087] delegated.c:3150 --- _main init_resolv() DONE
05:10.316 [6087] dl.c:171 --- dl_library(ssl)...
05:10.317 [6087] dl.c:233 --- [ssl] 0 dglibssl.so
05:10.321 [6087] dl.c:233 --- [ssl] FF340C78 libssl.so.0.9.8
05:10.322 [6087] dl.c:171 --- dl_library(z)...
05:10.322 [6087] dl.c:233 --- [z] 0 dglibz.so
05:10.323 [6087] dl.c:233 --- [z] 0 libz.so.0.9.8
05:10.324 [6087] dl.c:233 --- [z] FF341798 /usr/lib/libz.so
05:10.327 [6087] inets.c:418 --E unknown getyostname(update.microsoft.com)
-- }} ---- ERROR in initialization ----
04/18 15:05:10.33 [6087] 0+0: #### wait the first contact...
04/18 15:07:53.41 [6087] 0+0: #### got the first contact
04/18 15:07:53.41 [6087] 0+0: DeleGate SERVER RESTART: timeout
04/18 15:07:53.41 [6087] 0+0: NUM_HUPS=1 FD=[15]
04/18 15:07:53.41 [6087] 0+0: StickyKill(1): 0/0 killed
04/18 15:07:53.41 [6087] 0+0: DeleGate SERVER RESTART in progress...
04/18 15:07:53.41 [6087] 0+0: PWD: /opt/gemalto/delegate951/src
04/18 15:07:53.41 [6087] 0+0: EXEC: /opt/gemalto/delegate951/src/./delegated
04/18 15:07:53.43 [6087] 0+0: -- setCredhyCache /tmp/credhy_cache128 >>
/opt/gemalto/delegate951/act/credhy_cache128
04/18 15:07:53.43 [6087] 0+0: command PATH:
/opt/gemalto/delegate951/src/./delegated ->
/opt/gemalto/delegate951/src/./delega
ted
04/18 15:07:53.43 [6087] 0+0: PORT> -P8077/9
04/18 15:07:53.43 [6087] 0+0: ... gethostname(OTA)
04/18 15:07:53.43 [6087] 0+0: configuring default RESOLV ...
04/18 15:07:53.43 [6087] 0+0: ... gethostname()='OTA'
04/18 15:07:53.43 [6087] 0+0: ... SYS: OTA -> 192.168.11.136
04/18 15:07:53.43 [6087] 0+0: ## connect[5] refused (146)
04/18 15:07:53.43 [6087] 0+0: {R} No local NS (192.168.11.136:53)
04/18 15:07:53.43 [6087] 0+0: ... NIS not available (no default domain)
04/18 15:07:53.43 [6087] 0+0: ... export RES_ORDER=CFDS
04/18 15:07:53.43 [6087] 0+0: export RESOLV=cache,file,dns,sys (set by
default)
SRCSIGN=9.5.1:20070305034311+0900:3b9b14c5e1e34f38:Author@DeleGate.ORG
:lmz3FazLKFvmy5I9SvilekIgHFCFOjVhXlNAdsY2d3rgRR5l4ZHiJT
AFWW9eUgPd0ta2jNNoWNum9o7hzQl/C9dE+uQ2DfxUUhjba5c/vG9iGxGUhV7at+fnaCiZjhZBUdiYBTAQO7jQPz8pBSSy0WE+DLETEbqFIC35jDK6Xc4=^M
BLDSIGN=9.5.1:20070321152701+0700:3b9b14c5e1e34f38:support@gemalto..:-^M
04/18 15:07:53.44 [6087] 0+0: --INITIALIZATION START-07041815+0700: 9.5.1 on
SunOS/5.9--
04/18 15:07:53.44 [6087] 0+0: BINSHELL=/bin/sh
04/18 15:07:53.44 [6087] 0+0: DGROOT=/opt/gemalto/delegate951^M
04/18 15:07:53.44 [6087] 0+0: <DeleGate/9.5.1> [6087] -P8077 READY^M
04/18 15:07:53.44 [6087] 0+0: PORT= 8077/9 (31,141)
04/18 15:07:53.44 [6087] 0+0: OWNER=nobody => OWNER=gemuser/dba(gemuser/dba)
04/18 15:07:53.44 [6087] 0+0: REMITTABLE =
http,https/{80,443},gopher,ftp,wais
04/18 15:07:53.44 [6087] 0+0: --- [ssl] 0 dglibssl.so
04/18 15:07:53.44 [6087] 0+0: --- [ssl] FF340C38 libssl.so.0.9.8
04/18 15:07:53.44 [6087] 0+0: ---- [ssl] loaded 92 syms, unknown=0+0,
already=0
04/18 15:07:53.44 [6087] 0+0: +++ loaded OpenSSL 0.9.8e 23 Feb 2007
04/18 15:07:53.44 [6087] 0+0: --- [z] 0 dglibz.so
04/18 15:07:53.45 [6087] 0+0: --- [z] 0 libz.so.0.9.8
04/18 15:07:53.45 [6087] 0+0: --- [/usr/lib/libz.so]
04/18 15:07:53.45 [6087] 0+0: --- [z] FF341758 /usr/lib/libz.so
04/18 15:07:53.45 [6087] 0+0: ---- [z] loaded 9 syms, unknown=0+0, already=0
04/18 15:07:53.45 [6087] 0+0: {R} retrying AAAA [update.microsoft.com]
04/18 15:07:53.45 [6087] 0+0: gethostbyname(update.microsoft.com) unknown[
0.00s]
04/18 15:07:53.45 [6087] 0+0: ERROR CMAP/DST[1] update.microsoft.com ?
unknown
04/18 15:07:53.45 [6087] 0+0: ADMIN=support@gemalto.comprotocol=http(specialist)
04/18 15:07:53.45 [6087] 0+0: #### CACHE DISABLED #### Cache directory seems
not exist: /opt/gemalto/delegate951/cache
04/18 15:07:53.45 [6087] 0+0: MOUNT[0]X[3] /-/builtin/icons/* = default
04/18 15:07:53.45 [6087] 0+0: MOUNT[1]X[4] /-/* =
forbidden,from=!.RELIABLE,default
04/18 15:07:53.45 [6087] 0+0: MOUNT[2]X[0] /-* = default
04/18 15:07:53.45 [6087] 0+0: MOUNT[3]X[1] /=* = default
04/18 15:07:53.45 [6087] 0+0: MOUNT[4]X[5] /favicon.ico
builtin:icons/ysato/default.ico default,direction=fo,onerror=404,expi
res=15m
04/18 15:07:53.45 [6087] 0+0: MOUNT[5]X[2] /*
https://winapi.wireless.co.id/*
04/18 15:07:53.45 [6087] 0+0: #### stack size limit = 800000 (000000X)
04/18 15:07:53.45 [6087] 0+0: Stay open PIDFILE for accept() lock[fd=11]
04/18 15:07:53.45 [6087] 0+0: StickyReport[14,13]127.0.0.127:65535><
0.0.0.0:0
04/18 15:07:53.45 [6087] 0+0: env[26]
LIBPATH=.;/opt/gemalto/delegate951/src;/opt/gemalto/delegate951/lib;/opt/gemalto/delega
te951/src/.;/opt/gemalto/delegate951/etc
04/18 15:07:53.45 [6087] 0+0: env[29] RESOLV=cache,file,dns,sys
04/18 15:07:53.45 [6087] 0+0: arg[3] SERVER=http
04/18 15:07:53.45 [6087] 0+0: arg[4] FSV=sslway -ssl2 -Vrfy -CAfile
pems/TrivnetCA.crt -cert pems/ggs-delegate.crt -key pems/
ggs-delegate.key -pass pass:1234
04/18 15:07:53.45 [6087] 0+0: arg[5] MOUNT=/*
https://winapi.wireless.co.id/*
04/18 15:07:53.45 [6087] 0+0: arg[6] TLSCONF=-vd, scache:no
04/18 15:07:53.45 [6087] 0+0: arg[7] RES_WAIT=0
04/18 15:07:53.45 [6087] 0+0: arg[8] DGROOT=/opt/gemalto/delegate951
04/18 15:07:53.45 [6087] 0+0: DELEGATE_Modified[1]: 4625d1d9 000000000X
04/18 15:07:53.45 [6087] 0+0: NUM_HUPS=1
04/18 15:07:53.45 [6087] 0+0: --INITIALIZATION DONE-07041815+0700: 9.5.1 on
SunOS/5.9--
04/18 15:07:53.46 [6093] 1+0: -- Fork(SequentialServer): 6087 -> 6093
04/18 15:07:53.47 [6093] 1+1: (0) accepted [20] -@[192.168.11.116]OTA1:52574
(0.007s)(1)
04/18 15:07:53.47 [6093] 1+1: Proxy: host=OTA1; User-Agent: ; DIRECT
04/18 15:07:53.47 [6093] 1+1: HCKA:[0] close; host=OTA1; (User-Agent: )
04/18 15:07:53.47 [6093] 1+1: REQUEST - GET
/WinFacadeWeb/SmsServicesServlet?SMS%5fserviceName=get%5fbalance&SMS%5fsourceMsis
dn=628811051102&SMS%5fpin=1357 HTTP/1.1^M
04/18 15:07:53.47 [6093] 1+1: ***
/WinFacadeWeb/SmsServicesServlet?SMS%5fserviceName=get%5fbalance&SMS%5fsourceMsisdn=6288110
51102&SMS%5fpin=1357 =>
https://winapi.wireless.co.id/WinFacadeWeb/SmsServicesServlet?SMS%5fserviceName=get%5fbalance&SMS%5fs
ourceMsisdn=628811051102&SMS%5fpin=1357 ***
04/18 15:07:53.47 [6093] 1+1: REQUEST +M
https://winapi.wireless.co.id/WinFacadeWeb/SmsServicesServlet?SMS%5fserviceName=get%
5fbalance&SMS%5fsourceMsisdn=628811051102&SMS%5fpin=1357 HTTP/1.1^M
04/18 15:07:53.47 [6093] 1+1: ***
/WinFacadeWeb/SmsServicesServlet?SMS%5fserviceName=get%5fbalance&SMS%5fsourceMsisdn=6288110
51102&SMS%5fpin=1357 =>
https://winapi.wireless.co.id/WinFacadeWeb/SmsServicesServlet?SMS%5fserviceName=get%5fbalance&SMS%5fs
ourceMsisdn=628811051102&SMS%5fpin=1357 ***
04/18 15:07:53.47 [6093] 1+1: PATH>
https://winapi.wireless.co.id:443!OTA1:8077!OTA1:52574!anonymous@OTA1;1176883673
04/18 15:07:53.47 [6093] 1+1: REQUEST = [https://winapi.wireless.co.id:443/]
GET /WinFacadeWeb/SmsServicesServlet?SMS%5fservi
ceName=get%5fbalance&SMS%5fsourceMsisdn=628811051102&SMS%5fpin=1357
HTTP/1.1^M
04/18 15:07:53.47 [6093] 1+1: XHost: (0,0,1) winapi.wireless.co.id <=
gemhost:8077
04/18 15:07:53.47 [6093] 1+1: ConnectToServer connected [14] {
192.168.11.110:443 <- 192.168.11.116:52576} [0.001s]
04/18 15:07:53.47 [6093] 1+1: willSTLS_SV: ServerFlags=10
04/18 15:07:53.47 [6093] 1+1: HTTP => (winapi.wireless.co.id:443) GET
/WinFacadeWeb/SmsServicesServlet?SMS%5fserviceName=get%
5fbalance&SMS%5fsourceMsisdn=628811051102&SMS%5fpin=1357 HTTP/1.1^M
04/18 15:07:53.47 [6094] 1+1: -- Fork(FSV): 6093 -> 6094
04/18 15:07:53.48 [6094] 1+1: ## SSLway CFI_TYPE=FSV: -co is assumed
04/18 15:07:53.48 [6094] 1+1: ## SSLway start
04/18 15:07:53.49 [6094] 1+1: ## SSLway certfile loaded:
/opt/gemalto/delegate951/src/pems/ggs-delegate.crt
04/18 15:07:53.49 [6094] 1+1: ## SSLway passphrase for
pems/ggs-delegate.key-- OK
04/18 15:07:53.49 [6094] 1+1: ## SSLway keyfile loaded:
/opt/gemalto/delegate951/src/pems/ggs-delegate.key
04/18 15:07:53.49 [6094] 1+1: ## SSLway CAs =
[/opt/gemalto/delegate951/src/pems/TrivnetCA.crt][(null)]
04/18 15:07:53.49 [6094] 1+1: ## SSLway loadSession 0.000038 (0 0) / -1
04/18 15:07:53.49 [6094] 1+1: ## SSLway depth=1/-1 ok=1 0:"ok"
/C=IL/ST=Shefayim/L=Shefayim/O=Trivnet Ltd./OU=CS/CN=TrivnetCA
/emailAddress=support@trivnet..
04/18 15:07:53.50 [6094] 1+1: ## SSLway depth=0/-1 ok=1 0:"ok"
/C=ID/ST=Jakarta/L=Jakarta/O=PrimaCell Ltd./OU=Billing/CN=wina
pi.wireless.co.id/emailAddress=support@wireless..id
04/18 15:07:53.53 [6094] 1+1: ## SSLway connected
04/18 15:07:53.53 [6094] 1+1: ## SSLway -- 0.000083 start
04/18 15:07:53.53 [6094] 1+1: ## SSLway -- 0.000135 init done
04/18 15:07:53.53 [6094] 1+1: ## SSLway -- 0.000289 begin args
04/18 15:07:53.53 [6094] 1+1: ## SSLway -- 0.000305 end args
04/18 15:07:53.53 [6094] 1+1: ## SSLway -- 0.001227 end rand_seed
04/18 15:07:53.53 [6094] 1+1: ## SSLway -- 0.001430 nodelay set
04/18 15:07:53.53 [6094] 1+1: ## SSLway -- 0.001431 start con/acc
04/18 15:07:53.53 [6094] 1+1: ## SSLway -- 0.012863 ssl_conn() start
04/18 15:07:53.53 [6094] 1+1: ## SSLway -- 0.013015 loadSession NONE
04/18 15:07:53.53 [6094] 1+1: ## SSLway -- 0.013100 before connect
04/18 15:07:53.53 [6094] 1+1: ## SSLway -- 0.053517 after connect
04/18 15:07:53.53 [6094] 1+1: ## SSLway -- 0.054049 saveSession OK
04/18 15:07:53.53 [6094] 1+1: ## SSLway -- 0.054134 start relay ...
04/18 15:07:53.53 [6094] 1+1: ## SSLway server's cert. =
**subject<</C=ID/ST=Jakarta/L=Jakarta/O=PrimaCell Ltd./OU=Billing/CN
=winapi.wireless.co.id/emailAddress=support@wireless..id>>
**issuer<</C=IL/ST=Shefayim/L=Shefayim/O=Trivnet Ltd./OU=CS/CN=T
rivnetCA/emailAddress=support@trivnet..>>
04/18 15:07:53.53 [6094] 1+1: ## SSLway C-S: 221/221 -> 221/SSL
04/18 15:07:53.58 [6094] 1+1: ## SSLway S-C: 170/170 -> 170
04/18 15:07:53.58 [6094] 1+1: ## SSLway S-C: 4/4 -> 4
04/18 15:07:53.58 [6094] 1+1: ## SSLway S-C: 154/154 -> 154
04/18 15:07:53.58 [6094] 1+1: ## SSLway S-C: 2/2 -> 2
04/18 15:07:53.58 [6093] 1+1: #HT11 NO-response-buffering: chunked mode
04/18 15:07:53.58 [6093] 1+1: #HT11 --getChunk-Header: Transfer-Encoding:
chunked^M
04/18 15:07:53.58 [6093] 1+1: #HT11 SERVER ver[HTTP/1.1] conn[]
04/18 15:07:53.58 [6093] 1+1: #HT11 server KEEP-ALIVE
04/18 15:07:53.58 [6093] 1+1: #HT11 --putChunk-Header: Transfer-Encoding:
chunked^M
04/18 15:07:53.58 [6093] 1+1: HTTP/1.1 200 Content-{Type:text/plain
Encoding:[/chunked] Leng:0} Server:Apache/2.0.55 (Unix) m
od_ssl/2.0.55 OpenSSL/0.9.7d
04/18 15:07:53.92 [6094] 1+1: ## SSLway S-C: 5/5 -> 5
04/18 15:07:53.92 [6093] 1+1: HTTP transmitted:
170head+154/0body=>0txt+0bin->154/0, 8i/1o/0f/0.3
04/18 15:07:53.92 [6093] 1+1: #HT11 putServ(21/22) winapi.wireless.co.id:443
04/18 15:07:53.92 [6093] 1+1: disconnected [20] -@[192.168.11.116]OTA1:52574
(0.460s)(0)
04/18 15:07:53.92 [6093] 1+1: FSV=sslway in Keep-Alive(*1) nproc=1
04/18 15:07:53.92 [6093] 1+1: CFI process remaining (sv*1)
OTA1 - - [18/Apr/2007:15:07:53 +0700] "GET
https://winapi.wireless.co.id/WinFacadeWeb/SmsServicesServlet?SMS%5fserviceName=ge
t%5fbalance&SMS%5fsourceMsisdn=628811051102&SMS%5fpin=1357 HTTP/1.1" 200 154
0*0.004+0.441:W:0-
04/18 15:07:53.92 [6093] 1+1: StickyServer done
[nonStickyProtocol(http:https:https)] 1 req / 1 conn / 0 sec
04/18 15:07:53.92 [6094] 1+1: ## SSLway C-S EOF from the client
04/18 15:07:53.92 [6094] 1+1: ## SSLway S>> shutdown from server: 0
04/18 15:07:53.92 [6094] 1+1: ## SSLway done
04/18 15:09:45.95 [6095] 2+0: -- Fork(SequentialServer): 6087 -> 6095
04/18 15:09:45.95 [6095] 2+1: (0) accepted [48] -@[192.168.11.116]OTA1:52659
(0.006s)(1)
04/18 15:09:45.96 [6095] 2+1: Proxy: host=OTA1; User-Agent: ; DIRECT
04/18 15:09:45.96 [6095] 2+1: HCKA:[0] close; host=OTA1; (User-Agent: )
04/18 15:09:45.96 [6095] 2+1: REQUEST - GET
/WinFacadeWeb/SmsServicesServlet?SMS%5fserviceName=get%5fbalance&SMS%5fsourceMsis
dn=628811051102&SMS%5fpin=1357 HTTP/1.1^M
04/18 15:09:45.96 [6095] 2+1: ***
/WinFacadeWeb/SmsServicesServlet?SMS%5fserviceName=get%5fbalance&SMS%5fsourceMsisdn=6288110
51102&SMS%5fpin=1357 =>
https://winapi.wireless.co.id/WinFacadeWeb/SmsServicesServlet?SMS%5fserviceName=get%5fbalance&SMS%5fs
ourceMsisdn=628811051102&SMS%5fpin=1357 ***
04/18 15:09:45.96 [6095] 2+1: REQUEST +M
https://winapi.wireless.co.id/WinFacadeWeb/SmsServicesServlet?SMS%5fserviceName=get%
5fbalance&SMS%5fsourceMsisdn=628811051102&SMS%5fpin=1357 HTTP/1.1^M
04/18 15:09:45.96 [6095] 2+1: ***
/WinFacadeWeb/SmsServicesServlet?SMS%5fserviceName=get%5fbalance&SMS%5fsourceMsisdn=6288110
51102&SMS%5fpin=1357 =>
https://winapi.wireless.co.id/WinFacadeWeb/SmsServicesServlet?SMS%5fserviceName=get%5fbalance&SMS%5fs
ourceMsisdn=628811051102&SMS%5fpin=1357 ***
04/18 15:09:45.96 [6095] 2+1: PATH>
https://winapi.wireless.co.id:443!OTA1:8077!OTA1:52659!anonymous@OTA1;1176883785
04/18 15:09:45.96 [6095] 2+1: REQUEST = [https://winapi.wireless.co.id:443/]
GET /WinFacadeWeb/SmsServicesServlet?SMS%5fservi
ceName=get%5fbalance&SMS%5fsourceMsisdn=628811051102&SMS%5fpin=1357
HTTP/1.1^M
04/18 15:09:45.96 [6095] 2+1: XHost: (0,0,1) winapi.wireless.co.id <=
gemhost:8077
04/18 15:09:45.96 [6095] 2+1: ConnectToServer connected [14] {
192.168.11.110:443 <- 192.168.11.116:52660} [0.001s]
04/18 15:09:45.96 [6095] 2+1: willSTLS_SV: ServerFlags=10
04/18 15:09:45.96 [6095] 2+1: HTTP => (winapi.wireless.co.id:443) GET
/WinFacadeWeb/SmsServicesServlet?SMS%5fserviceName=get%
5fbalance&SMS%5fsourceMsisdn=628811051102&SMS%5fpin=1357 HTTP/1.1^M
04/18 15:09:45.96 [6096] 2+1: -- Fork(FSV): 6095 -> 6096
04/18 15:09:45.96 [6096] 2+1: ## SSLway CFI_TYPE=FSV: -co is assumed
04/18 15:09:45.96 [6096] 2+1: ## SSLway start
04/18 15:09:45.97 [6096] 2+1: ## SSLway certfile loaded:
/opt/gemalto/delegate951/src/pems/ggs-delegate.crt
04/18 15:09:45.97 [6096] 2+1: ## SSLway passphrase for
pems/ggs-delegate.key-- OK
04/18 15:09:45.97 [6096] 2+1: ## SSLway keyfile loaded:
/opt/gemalto/delegate951/src/pems/ggs-delegate.key
04/18 15:09:45.98 [6096] 2+1: ## SSLway CAs =
[/opt/gemalto/delegate951/src/pems/TrivnetCA.crt][(null)]
04/18 15:09:45.98 [6096] 2+1: ## SSLway loadSession 0.000494 (1 0) / 1
04/18 15:09:45.98 [6096] 2+1: ## SSLway connect failed
6096:error:1406D044:SSL routines:GET_SERVER_HELLO:internal
error:s2_clnt.c:528:
04/18 15:09:45.98 [6096] 2+1: builtin-SSLway: ssl_conn() failed
04/18 15:09:45.98 [6095] 2+1: HTTP relay_response: EOF at start
04/18 15:09:45.98 [6095] 2+1: #HT11 EOF from the client (2)
04/18 15:09:45.98 [6095] 2+1: #HT11 close svsokcs[20,21]
04/18 15:09:45.98 [6095] 2+1/1: WaitShutdown 1/0 xpid=0 errno=0/10 0 8 0
0.000
04/18 15:09:46.00 [6095] 2+1/1: WaitShutdown 1/0 xpid=6096 errno=0/10 0 8 0
0.016
04/18 15:09:46.00 [6095] 2+1/1: disconnected [48] -@[192.168.11.116]OTA1:52659
(0.053s)(0)
04/18 15:09:46.00 [6095] 2+1/1: CFI process none (0/1)
OTA1 - - [18/Apr/2007:15:09:45 +0700] "GET
https://winapi.wireless.co.id/WinFacadeWeb/SmsServicesServlet?SMS%5fserviceName=ge
t%5fbalance&SMS%5fsourceMsisdn=628811051102&SMS%5fpin=1357 HTTP/1.1" 500 0
0*0.000+0.000:P:0-
04/18 15:09:46.00 [6095] 2+1: StickyServer done
[nonStickyProtocol(http:https:https)] 1 req / 1 conn / 1 sec
04/18 15:10:52.13 [6099] 3+0: -- Fork(SequentialServer): 6087 -> 6099
04/18 15:10:52.13 [6099] 3+1: (0) accepted [46] -@[192.168.11.116]OTA1:52703
(0.006s)(1)
04/18 15:10:52.14 [6099] 3+1: Proxy: host=OTA1; User-Agent: ; DIRECT
04/18 15:10:52.14 [6099] 3+1: HCKA:[0] close; host=OTA1; (User-Agent: )
04/18 15:10:52.14 [6099] 3+1: REQUEST - GET
/WinFacadeWeb/SmsServicesServlet?SMS%5fserviceName=get%5fbalance&SMS%5fsourceMsis
dn=628811051102&SMS%5fpin=1357 HTTP/1.1^M
04/18 15:10:52.14 [6099] 3+1: ***
/WinFacadeWeb/SmsServicesServlet?SMS%5fserviceName=get%5fbalance&SMS%5fsourceMsisdn=6288110
51102&SMS%5fpin=1357 =>
https://winapi.wireless.co.id/WinFacadeWeb/SmsServicesServlet?SMS%5fserviceName=get%5fbalance&SMS%5fs
ourceMsisdn=628811051102&SMS%5fpin=1357 ***
04/18 15:10:52.14 [6099] 3+1: REQUEST +M
https://winapi.wireless.co.id/WinFacadeWeb/SmsServicesServlet?SMS%5fserviceName=get%
5fbalance&SMS%5fsourceMsisdn=628811051102&SMS%5fpin=1357 HTTP/1.1^M
04/18 15:10:52.14 [6099] 3+1: ***
/WinFacadeWeb/SmsServicesServlet?SMS%5fserviceName=get%5fbalance&SMS%5fsourceMsisdn=6288110
51102&SMS%5fpin=1357 =>
https://winapi.wireless.co.id/WinFacadeWeb/SmsServicesServlet?SMS%5fserviceName=get%5fbalance&SMS%5fs
ourceMsisdn=628811051102&SMS%5fpin=1357 ***
04/18 15:10:52.14 [6099] 3+1: PATH>
https://winapi.wireless.co.id:443!OTA1:8077!OTA1:52703!anonymous@OTA1;1176883852
04/18 15:10:52.14 [6099] 3+1: REQUEST = [https://winapi.wireless.co.id:443/]
GET /WinFacadeWeb/SmsServicesServlet?SMS%5fservi
ceName=get%5fbalance&SMS%5fsourceMsisdn=628811051102&SMS%5fpin=1357
HTTP/1.1^M
04/18 15:10:52.14 [6099] 3+1: XHost: (0,0,1) winapi.wireless.co.id <=
gemhost:8077
04/18 15:10:52.14 [6099] 3+1: ConnectToServer connected [14] {
192.168.11.110:443 <- 192.168.11.116:52704} [0.000s]
04/18 15:10:52.14 [6099] 3+1: willSTLS_SV: ServerFlags=10
04/18 15:10:52.14 [6099] 3+1: HTTP => (winapi.wireless.co.id:443) GET
/WinFacadeWeb/SmsServicesServlet?SMS%5fserviceName=get%
5fbalance&SMS%5fsourceMsisdn=628811051102&SMS%5fpin=1357 HTTP/1.1^M
04/18 15:10:52.14 [6100] 3+1: -- Fork(FSV): 6099 -> 6100
04/18 15:10:52.14 [6100] 3+1: ## SSLway CFI_TYPE=FSV: -co is assumed
04/18 15:10:52.14 [6100] 3+1: ## SSLway start
04/18 15:10:52.15 [6100] 3+1: ## SSLway certfile loaded:
/opt/gemalto/delegate951/src/pems/ggs-delegate.crt
04/18 15:10:52.15 [6100] 3+1: ## SSLway passphrase for
pems/ggs-delegate.key-- OK
04/18 15:10:52.15 [6100] 3+1: ## SSLway keyfile loaded:
/opt/gemalto/delegate951/src/pems/ggs-delegate.key
04/18 15:10:52.15 [6100] 3+1: ## SSLway CAs =
[/opt/gemalto/delegate951/src/pems/TrivnetCA.crt][(null)]
04/18 15:10:52.15 [6100] 3+1: ## SSLway loadSession 0.000458 (1 0) / 1
04/18 15:10:52.16 [6100] 3+1: ## SSLway connect failed
6100:error:1406D044:SSL routines:GET_SERVER_HELLO:internal
error:s2_clnt.c:528:
04/18 15:10:52.16 [6100] 3+1: builtin-SSLway: ssl_conn() failed
04/18 15:10:52.16 [6099] 3+1: HTTP relay_response: EOF at start
04/18 15:10:52.16 [6099] 3+1: #HT11 EOF from the client (2)
04/18 15:10:52.16 [6099] 3+1: #HT11 close svsokcs[20,21]
04/18 15:10:52.16 [6099] 3+1/1: WaitShutdown 1/0 xpid=0 errno=0/10 0 8 0
0.000
04/18 15:10:52.18 [6099] 3+1/1: WaitShutdown 1/0 xpid=6100 errno=0/10 0 8 0
0.018
04/18 15:10:52.18 [6099] 3+1/1: disconnected [46] -@[192.168.11.116]OTA1:52703
(0.054s)(0)
04/18 15:10:52.18 [6099] 3+1/1: CFI process none (0/1)
OTA1 - - [18/Apr/2007:15:10:52 +0700] "GET
https://winapi.wireless.co.id/WinFacadeWeb/SmsServicesServlet?SMS%5fserviceName=ge
t%5fbalance&SMS%5fsourceMsisdn=628811051102&SMS%5fpin=1357 HTTP/1.1" 500 0
0*0.000+0.000:P:0-
04/18 15:10:52.18 [6099] 3+1: StickyServer done
[nonStickyProtocol(http:https:https)] 1 req / 1 conn / 0 sec
04/18 15:12:09.54 [6101] 4+0: -- Fork(SequentialServer): 6087 -> 6101
04/18 15:12:09.54 [6101] 4+1: (0) accepted [31] -@[192.168.11.116]OTA1:52761
(0.006s)(1)
04/18 15:12:09.55 [6101] 4+1: Proxy: host=OTA1; User-Agent: ; DIRECT
04/18 15:12:09.55 [6101] 4+1: HCKA:[0] close; host=OTA1; (User-Agent: )
04/18 15:12:09.55 [6101] 4+1: REQUEST - GET
/WinFacadeWeb/SmsServicesServlet?SMS%5fserviceName=get%5fbalance&SMS%5fsourceMsis
dn=628811051102&SMS%5fpin=1357 HTTP/1.1^M
04/18 15:12:09.55 [6101] 4+1: ***
/WinFacadeWeb/SmsServicesServlet?SMS%5fserviceName=get%5fbalance&SMS%5fsourceMsisdn=6288110
51102&SMS%5fpin=1357 =>
https://winapi.wireless.co.id/WinFacadeWeb/SmsServicesServlet?SMS%5fserviceName=get%5fbalance&SMS%5fs
ourceMsisdn=628811051102&SMS%5fpin=1357 ***
04/18 15:12:09.55 [6101] 4+1: REQUEST +M
https://winapi.wireless.co.id/WinFacadeWeb/SmsServicesServlet?SMS%5fserviceName=get%
5fbalance&SMS%5fsourceMsisdn=628811051102&SMS%5fpin=1357 HTTP/1.1^M
04/18 15:12:09.55 [6101] 4+1: ***
/WinFacadeWeb/SmsServicesServlet?SMS%5fserviceName=get%5fbalance&SMS%5fsourceMsisdn=6288110
51102&SMS%5fpin=1357 =>
https://winapi.wireless.co.id/WinFacadeWeb/SmsServicesServlet?SMS%5fserviceName=get%5fbalance&SMS%5fs
ourceMsisdn=628811051102&SMS%5fpin=1357 ***
04/18 15:12:09.55 [6101] 4+1: PATH>
https://winapi.wireless.co.id:443!OTA1:8077!OTA1:52761!anonymous@OTA1;1176883929
04/18 15:12:09.55 [6101] 4+1: REQUEST = [https://winapi.wireless.co.id:443/]
GET /WinFacadeWeb/SmsServicesServlet?SMS%5fservi
ceName=get%5fbalance&SMS%5fsourceMsisdn=628811051102&SMS%5fpin=1357
HTTP/1.1^M
04/18 15:12:09.55 [6101] 4+1: XHost: (0,0,1) winapi.wireless.co.id <=
gemhost:8077
04/18 15:12:09.55 [6101] 4+1: ConnectToServer connected [14] {
192.168.11.110:443 <- 192.168.11.116:52762} [0.000s]
04/18 15:12:09.55 [6101] 4+1: willSTLS_SV: ServerFlags=10
04/18 15:12:09.55 [6101] 4+1: HTTP => (winapi.wireless.co.id:443) GET
/WinFacadeWeb/SmsServicesServlet?SMS%5fserviceName=get%
5fbalance&SMS%5fsourceMsisdn=628811051102&SMS%5fpin=1357 HTTP/1.1^M
04/18 15:12:09.55 [6102] 4+1: -- Fork(FSV): 6101 -> 6102
04/18 15:12:09.55 [6102] 4+1: ## SSLway CFI_TYPE=FSV: -co is assumed
04/18 15:12:09.55 [6102] 4+1: ## SSLway start
04/18 15:12:09.56 [6102] 4+1: ## SSLway certfile loaded:
/opt/gemalto/delegate951/src/pems/ggs-delegate.crt
04/18 15:12:09.56 [6102] 4+1: ## SSLway passphrase for
pems/ggs-delegate.key-- OK
04/18 15:12:09.56 [6102] 4+1: ## SSLway keyfile loaded:
/opt/gemalto/delegate951/src/pems/ggs-delegate.key
04/18 15:12:09.57 [6102] 4+1: ## SSLway CAs =
[/opt/gemalto/delegate951/src/pems/TrivnetCA.crt][(null)]
04/18 15:12:09.57 [6102] 4+1: ## SSLway loadSession 0.000466 (1 0) / 1
04/18 15:12:09.57 [6102] 4+1: ## SSLway connect failed
6102:error:1406D044:SSL routines:GET_SERVER_HELLO:internal
error:s2_clnt.c:528:
04/18 15:12:09.57 [6102] 4+1: builtin-SSLway: ssl_conn() failed
04/18 15:12:09.57 [6101] 4+1: HTTP relay_response: EOF at start
04/18 15:12:09.57 [6101] 4+1: #HT11 EOF from the client (2)
04/18 15:12:09.57 [6101] 4+1: #HT11 close svsokcs[20,21]
04/18 15:12:09.57 [6101] 4+1/1: WaitShutdown 1/0 xpid=0 errno=0/10 0 8 0
0.000
04/18 15:12:09.59 [6101] 4+1/1: WaitShutdown 1/0 xpid=6102 errno=0/10 0 8 0
0.017
04/18 15:12:09.59 [6101] 4+1/1: disconnected [31] -@[192.168.11.116]OTA1:52761
(0.053s)(0)
04/18 15:12:09.59 [6101] 4+1/1: CFI process none (0/1)
OTA1 - - [18/Apr/2007:15:12:09 +0700] "GET
https://winapi.wireless.co.id/WinFacadeWeb/SmsServicesServlet?SMS%5fserviceName=ge
t%5fbalance&SMS%5fsourceMsisdn=628811051102&SMS%5fpin=1357 HTTP/1.1" 500 0
0*0.000+0.000:P:0-
04/18 15:12:09.59 [6101] 4+1: StickyServer done
[nonStickyProtocol(http:https:https)] 1 req / 1 conn / 0 sec
==================================================================

Thanks a lot.
Chris

On 4/18/07, Yutaka Sato <feedback@delegate.org> wrote:
>
> Hi,
>
> In message <_A3709@delegate-en.ML_>
> on 04/17/07(19:32:01)
> you "Kwis Angelo" <phyhabdyi-6rjyzcltgs3r.ml@ml.delegate.org> wrote:
> |I have been running Delegate for the past few days.  However, there are
> some
> |instances where I cannot establish a session with the HTTPS site.  The
> |console logs show this error:
> |
> |5684:error:1406D044:SSL routines:GET_SERVER_HELLO:internal
> |error:s2_clnt.c:528
> |
> |Oftentimes, i need to restart Delegate so I can re-establish a session
> with
> |the HTTPS site once more.
>
> Do you mean it succeeds SSL at the beginning till the error?
> How oftern does it occur?
>
> |Also, according to the HTTPS Site guy, he does not see any request coming
> in
> |from Delegate...
> |
> |Can you help advise what this error mean?  Does this problem happen
> |regarding the client/server authentication phase?
> |
> |Here is how I start the process:
> |
> |./delegated -v -P$DELEDATE_LISTNER_PORT SERVER=http FSV="sslway -ssl2
> -Vrfy
> |-CAfile pems/TrivnetCA.crt -cert pems/ggs-delegate.crt -key pems/ggs-
> |delegate.key -pass pass:1234 " MOUNT="/* $HTTPS_HOST_URL/*" RES_WAIT=0
> |DGROOT=/opt/gemalto/delegate951 &
>
> You can see more detailed log of SSLway in the negotiation phase with
> the following option:
>
>   TLSCONF=-vd
>
> And you can disable the SSL session cache of DeleGate with this:
>
>   TLSCONF=scache:no
>
> Cheers,
> Yutaka
> --
>   9 9   Yutaka Sato <y.sato@delegate.org> http://delegate.org/y.sato/
> ( ~ )  National Institute of Advanced Industrial Science and Technology
> _<   >_ 1-1-4 Umezono, Tsukuba, Ibaraki, 305-8568 Japan
> Do the more with the less -- B. Fuller
>
[Top/Up] [oldest] - [Older+chunk] - [Newer+chunk] - [newest + Check]