OE 11 Webspeed delay start of agents when SSL is enabled

[Cecil]

OE:11
SP: none
OS: Centos 6.2
JAVA:

java version "1.6.0_32"
Java(TM) SE Runtime Environment (build 1.6.0_32-b05)
Java HotSpot(TM) Server VM (build 20.7-b02, mixed mode)
​

Here is strange situation. I'm starting the WebSpeed broker with SSL Enabled and it takes about 5 minutes for the agents to start. Why would this be?

See WebSpeed broker log:

[12/05/31@14:05:48.071+1200] P-030906 T-Main   1 --- --- /cmi/dev-uat/110/CMIReporter/OnlineReporting-DEV-UAT.broker.log opened.
[12/05/31@14:05:48.072+1200] P-030906 T-Main   1 --- --- Logging level set to = 2
[12/05/31@14:05:48.072+1200] P-030906 T-Main   1 --- --- Log entry types activated: UBroker.Basic,
[12/05/31@14:05:48.092+1200] P-030906 T-Main   2 UB Basic      ubroker version: v11.0.0 (05-Oct-2011) (8038)
[12/05/31@14:05:48.168+1200] P-030906 T-L-3045 2 UB Basic      Started listener thread: L-3045 (8043)
[COLOR=#ff0000][12/05/31@[B]14:05:48.183+1200[/B]] P-030906 T-L-3045 2 UB Basic      Server starting in SSL mode (12116)[/COLOR]
[COLOR=#008000][12/05/31@[B]14:11:26.777+1200[/B]] P-030906 T-L-3045 2 UB Basic      Starting 5 server threads ... (8053)[/COLOR]
[12/05/31@14:11:26.789+1200] P-030906 T-S-0001 2 UB Basic      Started server thread: S-0001. (8101)
[12/05/31@14:11:26.889+1200] P-030906 T-S-0002 2 UB Basic      Started server thread: S-0002. (8101)
[12/05/31@14:11:26.990+1200] P-030906 T-S-0003 2 UB Basic      Started server thread: S-0003. (8101)
[12/05/31@14:11:27.091+1200] P-030906 T-S-0004 2 UB Basic      Started server thread: S-0004. (8101)
[12/05/31@14:11:27.191+1200] P-030906 T-S-0005 2 UB Basic      Started server thread: S-0005. (8101)
[12/05/31@14:11:27.308+1200] P-030906 T-S-0001 2 UB Basic      Started server: /usr/dlc110/bin/_progres -web -logginglevel 2 -logfile /cmi/dev-uat/110/CMIReporter/OnlineReporting-DEV-UAT.server.log -ubpid 30906 -wtbhostname 192.168.1.12 -wtbport 55857 -wtaminport 3202 -wtamaxport 3502 -wtbname OnlineReporting-DEV-UAT -wtainstance 1 -ubpropfile /usr/dlc110/properties/ubroker.properties -logname OnlineReporting-DEV-UAT -logthreshold 0 -numlogfiles 3 -logentrytypes DB.Connects -ipver IPv4 -p web/objects/web-disp.p -weblogerror -db /cmi/dev-uat/110/CMIReporter/db/report.db
[12/05/31@14:11:27.308+1200] P-030906 T-S-0001 2 UB Basic       -cpstream UTF-8 -cpinternal UTF-8 (8108)
[12/05/31@14:11:27.403+1200] P-030906 T-S-0002 2 UB Basic      Started server: /usr/dlc110/bin/_progres -web -logginglevel 2 -logfile /cmi/dev-uat/110/CMIReporter/OnlineReporting-DEV-UAT.server.log -ubpid 30906 -wtbhostname 192.168.1.12 -wtbport 35316 -wtaminport 3202 -wtamaxport 3502 -wtbname OnlineReporting-DEV-UAT -wtainstance 2 -ubpropfile /usr/dlc110/properties/ubroker.properties -logname OnlineReporting-DEV-UAT -logthreshold 0 -numlogfiles 3 -logentrytypes DB.Connects -ipver IPv4 -p web/objects/web-disp.p -weblogerror -db /cmi/dev-uat/110/CMIReporter/db/report.db
[12/05/31@14:11:27.403+1200] P-030906 T-S-0002 2 UB Basic       -cpstream UTF-8 -cpinternal UTF-8 (8108)
[12/05/31@14:11:27.504+1200] P-030906 T-S-0003 2 UB Basic      Started server: /usr/dlc110/bin/_progres -web -logginglevel 2 -logfile /cmi/dev-uat/110/CMIReporter/OnlineReporting-DEV-UAT.server.log -ubpid 30906 -wtbhostname 192.168.1.12 -wtbport 43877 -wtaminport 3202 -wtamaxport 3502 -wtbname OnlineReporting-DEV-UAT -wtainstance 3 -ubpropfile /usr/dlc110/properties/ubroker.properties -logname OnlineReporting-DEV-UAT -logthreshold 0 -numlogfiles 3 -logentrytypes DB.Connects -ipver IPv4 -p web/objects/web-disp.p -weblogerror -db /cmi/dev-uat/110/CMIReporter/db/report.db
[12/05/31@14:11:27.504+1200] P-030906 T-S-0003 2 UB Basic       -cpstream UTF-8 -cpinternal UTF-8 (8108)
[12/05/31@14:11:27.604+1200] P-030906 T-S-0004 2 UB Basic      Started server: /usr/dlc110/bin/_progres -web -logginglevel 2 -logfile /cmi/dev-uat/110/CMIReporter/OnlineReporting-DEV-UAT.server.log -ubpid 30906 -wtbhostname 192.168.1.12 -wtbport 40556 -wtaminport 3202 -wtamaxport 3502 -wtbname OnlineReporting-DEV-UAT -wtainstance 4 -ubpropfile /usr/dlc110/properties/ubroker.properties -logname OnlineReporting-DEV-UAT -logthreshold 0 -numlogfiles 3 -logentrytypes DB.Connects -ipver IPv4 -p web/objects/web-disp.p -weblogerror -db /cmi/dev-uat/110/CMIReporter/db/report.db
[12/05/31@14:11:27.604+1200] P-030906 T-S-0004 2 UB Basic       -cpstream UTF-8 -cpinternal UTF-8 (8108)
[12/05/31@14:11:27.702+1200] P-030906 T-S-0005 2 UB Basic      Started server: /usr/dlc110/bin/_progres -web -logginglevel 2 -logfile /cmi/dev-uat/110/CMIReporter/OnlineReporting-DEV-UAT.server.log -ubpid 30906 -wtbhostname 192.168.1.12 -wtbport 58037 -wtaminport 3202 -wtamaxport 3502 -wtbname OnlineReporting-DEV-UAT -wtainstance 5 -ubpropfile /usr/dlc110/properties/ubroker.properties -logname OnlineReporting-DEV-UAT -logthreshold 0 -numlogfiles 3 -logentrytypes DB.Connects -ipver IPv4 -p web/objects/web-disp.p -weblogerror -db /cmi/dev-uat/110/CMIReporter/db/report.db
[12/05/31@14:11:27.702+1200] P-030906 T-S-0005 2 UB Basic       -cpstream UTF-8 -cpinternal UTF-8 (8108)
[12/05/31@14:11:28.803+1200] P-030906 T-NameServer 2 UB Basic      Broker registered with NameServer. (8556)

 

[Rob Fitzpatrick]

Good question. What is the process doing in that time? Do you see CPU activity for it? I/O? Can you trace the process? I don't know if proGetStack can be run against a broker, but if so maybe running it a few times to get a few stack traces would provide helpful info to attach to a support case.

 

[Cecil]

Hi Rob

I've monitored the CPU usage of the JAVA process whilst the broker & agents started up. The CPU usage for the JAVA process idled along around the 19% mark, peeked at 44% for a short burst. This was observed for the duration of the five minutes.

On a whim I rebooted the server and it's now there is no delay in the agents starting. Still very strange.

 

[Cecil]

Game changer. The agents are still taking along time to startup but also http requests are also taking along to complete or time out. Agghhhh. I can't tell if it java or the os?

It's fine without ssl setting.

 

[Rob Fitzpatrick]

Could be an 11.0 regression. You need to break out the monitoring tools and try to find out (a) what the bottleneck is (CPU/disk I/O/network) and (b) where it is; and/or open a case with TS. Also, turn on verbose logging with the log manager, to see what agents are up to.

Also, what kind of platform is this? A dev PC? A VM on an overloaded VM server? A decent server?

 

[TomBascom]

I would suspect network configuration. Something like improper DNS resolution or the lack of reverse name lookup capabilities.

 

[Cecil]

Could be an 11.0 regression. You need to break out the monitoring tools and try to find out (a) what the bottleneck is (CPU/disk I/O/network) and (b) where it is; and/or open a case with TS. Also, turn on verbose logging with the log manager, to see what agents are up to.

Also, what kind of platform is this? A dev PC? A VM on an overloaded VM server? A decent server?

The environment is a VM being build for pre-production. Sever loading is low on the physical machine.
I've enabled the logging to verbose mode. But the logs are not indicating any problem.

 

[Cecil]

I would suspect network configuration. Something like improper DNS resolution or the lack of reverse name lookup capabilities.

I've tested the dns setup and it's all correct no problems found. I've eliminated DNS by using only the host file and omitting the DNS server. This makes no difference to the delay.

I have the AdminServer automatically start when I server server boots-up. I have configure the broker to AutoStart and the delay is only a few seconds for the first time. Each subsequent stop & start of the broker takes the longer to start.

What is actually happening when the the broker process starts during the point where it says: "Server starting in SSL mode (12116) "?

Also I'm able to reproduce the problem on two different servers (Centos 5.6 & Centos 6.2).

I'm in the process of compiling issue to TeamProgress.

 

[Cecil]

Problem Solved - answer was in the release notes. DOH!

/dev/random was the problem. My server was not creating enough IRQ Interrupts because it's running in a virtualized environment.

Note: OE00203472    Type: Known Issue
Startup time of AppServer broker increases when SSL is enabled (Linux and UNIX)
---------------------------------
After upgrading to OpenEdge Appserver V11, the AppServer broker's startup time
might increase if SSL is enabled.  This happens if /dev/random is not populated
with random data.  The SSL libraries used by the AppServer broker require
several kilobytes of random data to properly secure SSL connections to the
broker. 

To resolve the issue, ensure that /dev/random is populated with enough random
data.  There are two possible solutions:

- Move /dev/random to /dev/random_bak, and then add a simlink from /dev/random
to /dev/urandom.  This makes /dev/random reference /dev/urandom.  Note that
/dev/urandom is less secure.

-  Install and run rngd, the random number generator daemon.  It increases the
entropy pool used /dev/random to provide random data.

A little bit more information about /dev/random & /dev/uradom
http://www.onkarjoshi.com/blog/191/device-dev-random-vs-urandom/