Resolved Slow Initial Client Connection with SSL Enabled AppServer

jamesmcfly

New Member
Hello,
We are currently using Progress 11.3 for Server (using Linux) and tried to use SSL for the security. However, it takes about 30 seconds for the client (using ABL) to connect to the server (the performance after the connection process is normal). If we do not enable the SSL, then it will connect immediately.

Progress KB - Client connection to a secure AppServer takes a long time
I found this link, but it did not solve the issue.

Below is the log from the appserver, we always got two Read Timed out error which takes 15 seconds for each error.

Code:
[18/02/02@10:50:13.368+0700] P-029052 T-L-3198 3 UB Basic      Recieved connection:: (8125)
[18/02/02@10:50:13.368+0700] P-029052 T-C-0001 2 UB Basic      ConnectionID= 192.168.0.49::vhpappserverssl::3198::89e3d5e9795a1936:7f103a21:1615498ddb8:-7fe1. (8096)
[18/02/02@10:50:28.384+0700] P-029052 T-C-0001 1 UB ----------- Error opening IOStreams : Read timed out. (8080)
[18/02/02@10:50:28.384+0700] P-029052 T-C-0001 1 UB ----------- java.net.SocketTimeoutException: Read timed out
[18/02/02@10:50:28.384+0700] P-029052 T-C-0001 1 UB -----------     at java.net.SocketInputStream.socketRead0(Native Method)
[18/02/02@10:50:28.384+0700] P-029052 T-C-0001 1 UB -----------     at java.net.SocketInputStream.read(SocketInputStream.java:150)
[18/02/02@10:50:28.384+0700] P-029052 T-C-0001 1 UB -----------     at java.net.SocketInputStream.read(SocketInputStream.java:121)
[18/02/02@10:50:28.384+0700] P-029052 T-C-0001 1 UB -----------     at com.rsa.sslj.x.bc.c(Unknown Source)
[18/02/02@10:50:28.384+0700] P-029052 T-C-0001 1 UB -----------     at com.rsa.sslj.x.bc.a(Unknown Source)
[18/02/02@10:50:28.384+0700] P-029052 T-C-0001 1 UB -----------     at com.rsa.sslj.x.bc.a(Unknown Source)
[18/02/02@10:50:28.384+0700] P-029052 T-C-0001 1 UB -----------     at com.rsa.sslj.x.bc.h(Unknown Source)
[18/02/02@10:50:28.384+0700] P-029052 T-C-0001 1 UB -----------     at com.rsa.sslj.x.cS.startHandshake(Unknown Source)
[18/02/02@10:50:28.384+0700] P-029052 T-C-0001 1 UB -----------     at com.rsa.ssl.SSLSocket.getInputStream(Unknown Source)
[18/02/02@10:50:28.384+0700] P-029052 T-C-0001 1 UB -----------     at com.progress.ubroker.broker.ubClientThread.openIOStreams(ubClientThread.java:565)
[18/02/02@10:50:28.384+0700] P-029052 T-C-0001 1 UB -----------     at com.progress.ubroker.broker.ubClientThread.processStartup(ubClientThread.java:1981)
[18/02/02@10:50:28.384+0700] P-029052 T-C-0001 1 UB -----------     at com.progress.ubroker.broker.ubASclientThread.processStartup(ubASclientThread.java:864)
[18/02/02@10:50:28.384+0700] P-029052 T-C-0001 1 UB -----------     at com.progress.ubroker.broker.ubClientThread.processEvent(ubClientThread.java:1238)
[18/02/02@10:50:28.384+0700] P-029052 T-C-0001 1 UB -----------     at com.progress.ubroker.broker.ubClientThread.mainline(ubClientThread.java:438)
[18/02/02@10:50:28.384+0700] P-029052 T-C-0001 1 UB -----------     at com.progress.ubroker.broker.ubClientThread.run(ubClientThread.java:359)
[18/02/02@10:50:28.385+0700] P-029052 T-C-0001 2 UB Basic      Client disconnected : 192.168.0.179. (8534)
[18/02/02@10:50:28.385+0700] P-029052 T-L-3198 3 UB Basic      admin error response received: 4. (8067)
[18/02/02@10:50:28.391+0700] P-029052 T-L-3198 3 UB Basic      Recieved connection:: (8125)
[18/02/02@10:50:28.391+0700] P-029052 T-C-0001 2 UB Basic      ConnectionID= 192.168.0.49::vhpappserverssl::3198::89e3d5e9795a1936:7f103a21:1615498ddb8:-7fe0. (8096)
[18/02/02@10:50:43.408+0700] P-029052 T-C-0001 1 UB ----------- Error opening IOStreams : Read timed out. (8080)
[18/02/02@10:50:43.408+0700] P-029052 T-C-0001 1 UB ----------- java.net.SocketTimeoutException: Read timed out
[18/02/02@10:50:43.408+0700] P-029052 T-C-0001 1 UB -----------     at java.net.SocketInputStream.socketRead0(Native Method)
[18/02/02@10:50:43.408+0700] P-029052 T-C-0001 1 UB -----------     at java.net.SocketInputStream.read(SocketInputStream.java:150)
[18/02/02@10:50:43.408+0700] P-029052 T-C-0001 1 UB -----------     at java.net.SocketInputStream.read(SocketInputStream.java:121)
[18/02/02@10:50:43.408+0700] P-029052 T-C-0001 1 UB -----------     at com.rsa.sslj.x.bc.c(Unknown Source)
[18/02/02@10:50:43.408+0700] P-029052 T-C-0001 1 UB -----------     at com.rsa.sslj.x.bc.a(Unknown Source)
[18/02/02@10:50:43.408+0700] P-029052 T-C-0001 1 UB -----------     at com.rsa.sslj.x.bc.a(Unknown Source)
[18/02/02@10:50:43.408+0700] P-029052 T-C-0001 1 UB -----------     at com.rsa.sslj.x.bc.h(Unknown Source)
[18/02/02@10:50:43.408+0700] P-029052 T-C-0001 1 UB -----------     at com.rsa.sslj.x.cS.startHandshake(Unknown Source)
[18/02/02@10:50:43.408+0700] P-029052 T-C-0001 1 UB -----------     at com.rsa.ssl.SSLSocket.getInputStream(Unknown Source)
[18/02/02@10:50:43.408+0700] P-029052 T-C-0001 1 UB -----------     at com.progress.ubroker.broker.ubClientThread.openIOStreams(ubClientThread.java:565)
[18/02/02@10:50:43.408+0700] P-029052 T-C-0001 1 UB -----------     at com.progress.ubroker.broker.ubClientThread.processStartup(ubClientThread.java:1981)
[18/02/02@10:50:43.408+0700] P-029052 T-C-0001 1 UB -----------     at com.progress.ubroker.broker.ubASclientThread.processStartup(ubASclientThread.java:864)
[18/02/02@10:50:43.408+0700] P-029052 T-C-0001 1 UB -----------     at com.progress.ubroker.broker.ubClientThread.processEvent(ubClientThread.java:1238)
[18/02/02@10:50:43.408+0700] P-029052 T-C-0001 1 UB -----------     at com.progress.ubroker.broker.ubClientThread.mainline(ubClientThread.java:438)
[18/02/02@10:50:43.408+0700] P-029052 T-C-0001 1 UB -----------     at com.progress.ubroker.broker.ubClientThread.run(ubClientThread.java:359)
[18/02/02@10:50:43.409+0700] P-029052 T-C-0001 2 UB Basic      Client disconnected : 192.168.0.179. (8534)
[18/02/02@10:50:43.409+0700] P-029052 T-L-3198 3 UB Basic      admin error response received: 4. (8067)
[18/02/02@10:50:43.412+0700] P-029052 T-L-3198 3 UB Basic      Recieved connection:: (8125)
[18/02/02@10:50:43.412+0700] P-029052 T-C-0001 2 UB Basic      ConnectionID= 192.168.0.49::vhpappserverssl::3198::89e3d5e9795a1936:7f103a21:1615498ddb8:-7fdf. (8096)
[18/02/02@10:50:43.543+0700] P-029052 T-C-0001 2 UB Basic      Client connected : 192.168.0.179. (8533)
[18/02/02@10:50:43.544+0700] P-029052 T-C-0001 2 UB Basic      The client requested ASK version= 1.0  capabilities= denyClientASK,allowServerASK. (13769)
[18/02/02@10:50:43.544+0700] P-029052 T-C-0001 2 UB Basic      The negotiated ASK version= 1.0  capabilities= denyServerASK,denyClientASK.  ASK protocol is disabled for this connection. (15256)
[18/02/02@10:51:05.312+0700] P-029052 T-C-0001 3 UB Basic      Enqueued request UBRQ_INIT_RQ issued to S-0002 requestID= tSRI+tPdRI02FEMYABo9iw
[18/02/02@10:51:05.313+0700] P-029052 T-C-0001 3 UB Basic      Enqueued request UBRQ_WRITEDATALAST issued to S-0002 requestID= tSRI+tPdRI02FEMYABo9iw
[18/02/02@10:51:05.313+0700] P-029052 T-C-0001 3 UB Basic      Request for 192.168.0.49::vhpappserverssl::3198::89e3d5e9795a1936:7f103a21:1615498ddb8:-7fdf issued to S-0002. (8535)
[18/02/02@10:51:05.662+0700] P-029052 T-C-0001 2 UB Basic      Client disconnected : 192.168.0.179. (8534)
[18/02/02@10:51:08.317+0700] P-029052 T-S-0002 3 UB Basic      got PROCSTATS msg: rqCnt= 1 pktsSentCnt= 1 pktsRcvdCnt= 1
[18/02/02@10:51:08.317+0700] P-029052 T-S-0002 3 UB Basic          procStatsData= htpchar.p|none|NON-PERSISTENT|1|0|0|0|0|4|1

We prefer to solve the issue in Progress 11.3, without upgrading to Progress 11.6.

Thank you

Christofer
 

jamesmcfly

New Member
Hello Cringer,
Yes, I am aware that 11.3 is officially retired, but it would be the best if there are solution for this issue. Is it possible that each server using Progress 11.3 experience the same issue when using SSL? I believe there are some setting needed to be changed.
We prefer solving this problem with Progress 11.3, since we have a lot of customers (about 1000), and 90% of them are now using Progress 11.3. It would be very hard for us to upgrade each of them in order to use SSL.
 

RealHeavyDude

Well-Known Member
I've used SSL/TLS connection from 10.0A to 11.6.3 with no performance problems for connecting whatsoever. Is the client also 11.3 or is the client 11.6+ ?
 

jamesmcfly

New Member
Hm.. That is weird.

Is there anything in the appserver's setting that may cause this?
We usually use State-Free mode when creating a new AppServer. We only set the Port, PROPATH and startup parameter for the Database setting.
Below is the appserver properties:

Code:
OpenEdge Release 11.3 as of Wed Jul 17 16:45:16 EDT 2013


Connecting to Progress AdminServer using rmi://localhost:20931/Chimera (8280)
Searching for vhpappserverssl (8288)
Connecting to vhpappserverssl  (8276)

Active properties
=================
4glSrcCompile=0
PROPATH=.:/usr1/wrk:/usr1/vhp/vhplib/:/usr1/vhp/vhplib/vhpbl11.pl:/usr1/wrk:/usr1/vhp/vhplib/:/usr1/vhp/vhplib/vhpbl11.pl
admSrvrRegisteredRetry=6
admSrvrRegisteredRetryInterval=3000
agentDetailTimeout(*)=10
allowRuntimeUpdates=0
appServerKeepaliveCapabilities=denyClientASK,denyServerASK
appserviceNameList=vhpappserverssl
autoStart=0
autoTrimTimeout(*)=1800
brkrDebuggerEnabled(*)=0
brkrDebuggerKeyAlias(*)=my_cert
brkrDebuggerKeyAliasPassword(*)=
brkrDebuggerPassphrase(*)=
brkrDebuggerPortNumber(*)=3099
brkrDebuggerSSLEnable(*)=0
brkrDebuggerUseBrokerAlias(*)=1
brkrLogAppend=1
brkrLogEntries=0
brkrLogEntryTypes(*)=UBroker.Basic
brkrLogThreshold=0
brkrLoggingLevel(*)=3 (0x3)
brkrNumLogFiles=3
brkrSpinInterval=3000
brokerLogFile=/usr1/wrk/vhpappserverssl.broker.log
certStorePath=/usr1/dlc/certs/
classMain=com.progress.ubroker.broker.ubroker
clientThreadPriority=5
collectStatsData(*)=1
compressionEnable=0
connectingTimeout(*)=60
controllingNameServer=NS1
debuggerEnabled=0
defaultService=false
description=AppServer Broker
environment=vhpappserverssl
flushStatsData(*)=255
groupName=
hostName=
infoVersion=9010
initialSrvrInstance=5
ipver=IPv4
jvmArgs=
jvmStartArgs=
keyAlias=my_cert
keyAliasPasswd=
keyStorePasswd=
keyStorePath=/usr1/dlc/keys/
listenerThreadPriority=6
maxClientInstance=512
maxIdleServers=10
maxSrvrInstance=10
minIdleServers=1
minSrvrInstance=1
mqBrkrLogAppend=1
mqBrkrLogEntries=0
mqBrkrLogEntryTypes=UBroker.Basic
mqBrkrLogThreshold=0
mqBrkrLoggingLevel=2
mqBrkrNumLogFiles=3
mqBrokerLogFile=/usr1/wrk/vhpappserverssl.mqbroker.log
mqEnabled=0
mqServerLogFile=/usr1/wrk/vhpappserverssl.mqserver.log
mqSrvrLogAppend=1
mqSrvrLogEntries=0
mqSrvrLogEntryTypes=UBroker.Basic
mqSrvrLogThreshold=0
mqSrvrLoggingLevel=2
mqSrvrNumLogFiles=3
noSessionCache=false
operatingMode=State-free
parentWatchdogInterval=3000
password=
portNumber=3198
priorityWeight(*)=0
publishDir=
queueLimit=0
registerNameServer=true
registrationMode=Register-IP
registrationRetry=30
requestTimeout(*)=15
rmiWatchdogInterval(*)=60
serverASKActivityTimeout=60
serverASKResponseTimeout=60
serverLifespan=0
serverLifespanPadding=5
serverThreadPriority=5
sessionTimeout=180
soTimeout=0
srvrActivateProc(*)=
srvrConnectProc(*)=
srvrDeactivateProc(*)=
srvrDisconnProc(*)=
srvrExecFile(*)=/usr1/dlc/bin/_proapsv
srvrExecutionTimeLimit=0
srvrLogAppend=1
srvrLogEntries=0
srvrLogEntryTypes(*)=ASPlumbing,DB.Connects
srvrLogFile=/usr1/wrk/vhpappserverssl.server.log
srvrLogThreshold=0
srvrLogWatchdogInterval=60
srvrLoggingLevel(*)=2
srvrMaxPort(*)=2202
srvrMinPort(*)=2002
srvrNumLogFiles=3
srvrSelectionScheme=0
srvrShutdownProc(*)=
srvrStartupParam(*)=-db /usr1/vhpdb/vhp.db -d dmy
srvrStartupProc(*)=
srvrStartupProcParam(*)=
srvrStartupTimeout(*)=3
sslAlgorithms=
sslEnable=true
userName=
uuid=89e3d5e9795a1936:6508699f:1614fa0830d:-718b
watchdogThreadPriority=6
workDir=/usr1/wrk
 

jamesmcfly

New Member
Hi all,
We finally got time to review the code. It turns out that the program is trying to connect to the AppServer without SSL first and then connect with SLL. This is done so that the program can connect to SSL enabled and not SSL enabled AppServer.
The connection process without SSL (to SSL enabled AppServer) took quite a long time before it fails. However, if we try to connect using SSL to not SSL enabled AppServer, it fails faster.
So the trick was to change the order, try to connect with SSL and if it failes, try to connect without SSL. It runs much faster.
 
Top