AppServer problems

jdpjamesp

jdpjamesp

ProgressTalk.com Moderator
Staff member
Hi folks,

a strange one this that I can't get to the bottom of (probably because I don't know a hug amount about AppServers).

I have a local copy of our production system for development purposes. The system has an AppServer for big queries (mostly). From time to time, in my local environment the AppServer seems to die and I can't restart it without restarting my PC. I'm running
Product Name : Progress
Install Path : C:\Progress\OpenEdge
Version : 10.2A
Service Pack : 03
Temp. Fix : 00
Build : 1390

Live.Broker.Log before the AppServer dies:
Code: 
[12/02/09@09:22:55.468+0000] P-005660 T-Main   1 --- --- C:\OpenEdge\WRK\Live.broker.log opened.
[12/02/09@09:22:55.468+0000] P-005660 T-Main   1 --- --- Logging level set to = 2
[12/02/09@09:22:55.468+0000] P-005660 T-Main   1 --- --- Log entry types activated: UBroker.Basic,
[12/02/09@09:22:55.562+0000] P-005660 T-Main   2 UB Basic      ubroker version: v102A (20-Jan-10) (8038)
[12/02/09@09:22:55.656+0000] P-005660 T-L-5162 2 UB Basic      Started listener thread: L-5162 (8043)
[12/02/09@09:22:55.687+0000] P-005660 T-L-5162 2 UB Basic      Starting 5 server threads ... (8053)
[12/02/09@09:22:55.718+0000] P-005660 T-S-0001 2 UB Basic      Started server thread: S-0001. (8101)
[12/02/09@09:22:55.812+0000] P-005660 T-S-0002 2 UB Basic      Started server thread: S-0002. (8101)
[12/02/09@09:22:55.906+0000] P-005660 T-S-0003 2 UB Basic      Started server thread: S-0003. (8101)
[12/02/09@09:22:56.015+0000] P-005660 T-S-0004 2 UB Basic      Started server thread: S-0004. (8101)
[12/02/09@09:22:56.109+0000] P-005660 T-S-0005 2 UB Basic      Started server thread: S-0005. (8101)
[12/02/09@09:22:56.468+0000] P-005660 T-S-0002 2 UB Basic      Started server: "C:\Progress\OpenEdge\bin\_proapsv.exe" -logginglevel 2 -logfile "C:\OpenEdge\WRK\Live.server.log" -ubpid 5660 -Ms 1 -logname Live -logentrytypes ASPlumbing,DB.Connects -logthreshold 0 -numlogfiles 3 -ASID 2 -ubpropfile "C:\Progress\OpenEdge\properties\ubroker.properties" -ipver IPv4 -pf E:\WorkSpace\HOME\appserver.pf (8108)
[12/02/09@09:22:56.468+0000] P-005660 T-S-0003 2 UB Basic      Started server: "C:\Progress\OpenEdge\bin\_proapsv.exe" -logginglevel 2 -logfile "C:\OpenEdge\WRK\Live.server.log" -ubpid 5660 -Ms 1 -logname Live -logentrytypes ASPlumbing,DB.Connects -logthreshold 0 -numlogfiles 3 -ASID 3 -ubpropfile "C:\Progress\OpenEdge\properties\ubroker.properties" -ipver IPv4 -pf E:\WorkSpace\HOME\appserver.pf (8108)
[12/02/09@09:22:56.468+0000] P-005660 T-S-0001 2 UB Basic      Started server: "C:\Progress\OpenEdge\bin\_proapsv.exe" -logginglevel 2 -logfile "C:\OpenEdge\WRK\Live.server.log" -ubpid 5660 -Ms 1 -logname Live -logentrytypes ASPlumbing,DB.Connects -logthreshold 0 -numlogfiles 3 -ASID 1 -ubpropfile "C:\Progress\OpenEdge\properties\ubroker.properties" -ipver IPv4 -pf E:\WorkSpace\HOME\appserver.pf (8108)
[12/02/09@09:22:56.531+0000] P-005660 T-S-0004 2 UB Basic      Started server: "C:\Progress\OpenEdge\bin\_proapsv.exe" -logginglevel 2 -logfile "C:\OpenEdge\WRK\Live.server.log" -ubpid 5660 -Ms 1 -logname Live -logentrytypes ASPlumbing,DB.Connects -logthreshold 0 -numlogfiles 3 -ASID 4 -ubpropfile "C:\Progress\OpenEdge\properties\ubroker.properties" -ipver IPv4 -pf E:\WorkSpace\HOME\appserver.pf (8108)
[12/02/09@09:22:56.625+0000] P-005660 T-S-0005 2 UB Basic      Started server: "C:\Progress\OpenEdge\bin\_proapsv.exe" -logginglevel 2 -logfile "C:\OpenEdge\WRK\Live.server.log" -ubpid 5660 -Ms 1 -logname Live -logentrytypes ASPlumbing,DB.Connects -logthreshold 0 -numlogfiles 3 -ASID 5 -ubpropfile "C:\Progress\OpenEdge\properties\ubroker.properties" -ipver IPv4 -pf E:\WorkSpace\HOME\appserver.pf (8108)
[12/02/09@09:23:28.750+0000] P-005660 T-S-0001 2 UB Basic      Server Port = 2005 PID = 4248. (8114)
[12/02/09@09:23:28.765+0000] P-005660 T-S-0003 2 UB Basic      Server Port = 2006 PID = 4264. (8114)
[12/02/09@09:23:28.765+0000] P-005660 T-S-0005 2 UB Basic      Server Port = 2004 PID = 4320. (8114)
[12/02/09@09:23:28.765+0000] P-005660 T-S-0004 2 UB Basic      Server Port = 2003 PID = 4272. (8114)
[12/02/09@09:23:28.765+0000] P-005660 T-S-0002 2 UB Basic      Server Port = 2002 PID = 4252. (8114)
[12/02/09@09:23:28.828+0000] P-005660 T-NameServer 2 UB Basic      Broker registered with NameServer. (8556)
[12/02/09@09:53:28.765+0000] P-005660 T-serverWatchdog 2 UB Basic      Shutdown requested: S-0001 ... (8051)
[12/02/09@09:53:28.781+0000] P-005660 T-serverWatchdog 2 UB Basic      Shutdown requested: S-0003 ... (8051)
[12/02/09@09:53:28.812+0000] P-005660 T-serverWatchdog 2 UB Basic      Shutdown requested: S-0005 ... (8051)
[12/02/09@09:53:28.812+0000] P-005660 T-serverWatchdog 2 UB Basic      Shutdown requested: S-0004 ... (8051)

Then when I try to restart:
Code: 
[12/02/09@13:59:40.500+0000] P-004832 T-Main   1 --- --- C:\OpenEdge\WRK\Live.broker.log opened.
[12/02/09@13:59:40.500+0000] P-004832 T-Main   1 --- --- Logging level set to = 2
[12/02/09@13:59:40.500+0000] P-004832 T-Main   1 --- --- Log entry types activated: UBroker.Basic,
[12/02/09@13:59:40.578+0000] P-004832 T-Main   2 UB Basic      ubroker version: v102A (20-Jan-10) (8038)
[12/02/09@13:59:40.812+0000] P-004832 T-L-5162 2 UB Basic      Started listener thread: L-5162 (8043)
[12/02/09@13:59:40.843+0000] P-004832 T-L-5162 1 UB ---------- Could not listen on port: 5162 (8044)
[12/02/09@13:59:40.843+0000] P-004832 T-L-5162 1 UB ---------- java.net.BindException: Address already in use: JVM_Bind
[12/02/09@13:59:40.843+0000] P-004832 T-L-5162 1 UB ----------     at java.net.PlainSocketImpl.socketBind(Native Method)
[12/02/09@13:59:40.843+0000] P-004832 T-L-5162 1 UB ----------     at java.net.PlainSocketImpl.bind(PlainSocketImpl.java:359)
[12/02/09@13:59:40.843+0000] P-004832 T-L-5162 1 UB ----------     at java.net.ServerSocket.bind(ServerSocket.java:319)
[12/02/09@13:59:40.843+0000] P-004832 T-L-5162 1 UB ----------     at java.net.ServerSocket.<init>(ServerSocket.java:185)
[12/02/09@13:59:40.843+0000] P-004832 T-L-5162 1 UB ----------     at java.net.ServerSocket.<init>(ServerSocket.java:141)
[12/02/09@13:59:40.843+0000] P-004832 T-L-5162 1 UB ----------     at com.progress.ubroker.broker.ubListenerPort.getServerSocket(ubListenerPort.java:366)
[12/02/09@13:59:40.843+0000] P-004832 T-L-5162 1 UB ----------     at com.progress.ubroker.broker.ubListenerPort.getListenerSocket(ubListenerPort.java:346)
[12/02/09@13:59:40.843+0000] P-004832 T-L-5162 1 UB ----------     at com.progress.ubroker.broker.ubListenerPort.<init>(ubListenerPort.java:119)
[12/02/09@13:59:40.843+0000] P-004832 T-L-5162 1 UB ----------     at com.progress.ubroker.broker.ubListenerThread.initializeListenerThread(ubListenerThread.java:503)
[12/02/09@13:59:40.843+0000] P-004832 T-L-5162 1 UB ----------     at com.progress.ubroker.broker.ubListenerThread.run(ubListenerThread.java:380)
[12/02/09@13:59:40.843+0000] P-004832 T-L-5162 1 UB ---------- Exception unbinding broker (not bound) : Live (8525)
[12/02/09@13:59:41.843+0000] P-004832 T-Main   2 UB Basic      ubroker v102A (20-Jan-10) done. (8041)
[12/02/09@13:59:41.843+0000] P-004832 T-Main   1 --- --- Log Closed

The Server log has nothing since 09:53.

Any thoughts? Need more info?
 
I'm guessing the

Could not listen on port: 5162 (8044)

is the pertinent part. So the port's tied up. Is there anything I can do to flush it out?
 
There is probably an old broker process already running - that is the most common issue with errors like "Could not listen on port: 5162 (8044) Address already in use" errors.

Get the sysinternals tools and see if you can find the old process or maybe use task mgr. Also explains why it works after you restart the pc.
 
TCPView will show you in real time all of your processes with network activity. Sort by local port to find who's listening on 5162. It will give you the process name and PID.
 
Cringer said:
Hi folks,

a strange one this that I can't get to the bottom of (probably because I don't know a hug amount about AppServers).
Click to expand...

You should hug your AppServer every now and then to keep it happy. ;-)

Cringer said:
Live.Broker.Log before the AppServer dies:
Code: 
snip
[12/02/09@09:22:55.687+0000] P-005660 T-L-5162 2 UB Basic      Starting 5 server threads ... (8053)
[12/02/09@09:22:55.718+0000] P-005660 T-S-0001 2 UB Basic      Started server thread: S-0001. (8101)
[12/02/09@09:22:55.812+0000] P-005660 T-S-0002 2 UB Basic      Started server thread: S-0002. (8101)
[12/02/09@09:22:55.906+0000] P-005660 T-S-0003 2 UB Basic      Started server thread: S-0003. (8101)
[12/02/09@09:22:56.015+0000] P-005660 T-S-0004 2 UB Basic      Started server thread: S-0004. (8101)
[12/02/09@09:22:56.109+0000] P-005660 T-S-0005 2 UB Basic      Started server thread: S-0005. (8101)
snip
[12/02/09@09:53:28.765+0000] P-005660 T-serverWatchdog 2 UB Basic      Shutdown requested: S-0001 ... (8051)
[12/02/09@09:53:28.781+0000] P-005660 T-serverWatchdog 2 UB Basic      Shutdown requested: S-0003 ... (8051)
[12/02/09@09:53:28.812+0000] P-005660 T-serverWatchdog 2 UB Basic      Shutdown requested: S-0005 ... (8051)
[12/02/09@09:53:28.812+0000] P-005660 T-serverWatchdog 2 UB Basic      Shutdown requested: S-0004 ... (8051)
Click to expand...

OK Watson, what's missing? Indeed number two is not listening. The AppServer agent is probably hanging in a limbo state or running around in circles refusing to look up and listen to the broker. If you check windows task manager you will see that an _proapsv process is still running (in this case with PID4252). If you kill it the broker can continue to shut down.

If you install OpenEdge Explorer (its a free separate install for 10.2A) it will show you the agents still running and allow you to kill individual agents.


P-005660 T-S-0002 2 UB Basic Server Port = 2002 PID = 4252. (8114)
 
Thanks for the replies. I will give that a go next time it happens. Apparently my colleagues have had similar problems on port 5162 and therefore run on a different port and have had no issues. So fingers crossed... :)
 
You must log in or register to reply here.
Back
Top