While testing the graceful cluster restart (we internally call
"reload-cluster" to differentiate from a "real" restart in our QA
environment we encountered the following problem:
2008-06-09 10:55:49,000 [-] [RMI TCP Connection(5)-10.10.3.87] INFO
ServiceBusManager Requesting a graceful shutdown at : Mon Jun 09
10:55:49 CEST 2008 in a
maximum of : 10 seconds
2008-06-09 10:55:49,000 [-] [RMI TCP Connection(5)-10.10.3.87] INFO
ServiceBusManager Putting transport listners, senders and tasks into
maintenence mode..
2008-06-09 10:55:49,001 [-] [RMI TCP Connection(5)-10.10.3.87] INFO
HttpCoreNIOListener Listener paused
2008-06-09 10:55:49,001 [-] [RMI TCP Connection(5)-10.10.3.87] INFO
HttpCoreNIOListener Listener paused
2008-06-09 10:55:49,001 [-] [RMI TCP Connection(5)-10.10.3.87] INFO
VFSTransportListener Listener paused
2008-06-09 10:55:49,001 [-] [RMI TCP Connection(5)-10.10.3.87] INFO
MailTransportListener Listener paused
2008-06-09 10:55:49,001 [-] [RMI TCP Connection(5)-10.10.3.87] INFO
HttpCoreNIOSender Sender paused
2008-06-09 10:55:49,001 [-] [RMI TCP Connection(5)-10.10.3.87] INFO
HttpCoreNIOSender Sender paused
2008-06-09 10:55:49,001 [-] [RMI TCP Connection(5)-10.10.3.87] INFO
VFSTransportSender Sender paused
2008-06-09 10:55:49,001 [-] [RMI TCP Connection(5)-10.10.3.87] INFO
JMSSender Sender paused
2008-06-09 10:55:49,006 [-] [RMI TCP Connection(5)-10.10.3.87] INFO
ServiceBusManager [ESB] Entered maintenence mode
2008-06-09 10:55:49,007 [-] [RMI TCP Connection(5)-10.10.3.87] INFO
ServiceBusManager All transport threads and tasks are idle and no
pending callbacks..
2008-06-09 10:55:49,007 [-] [RMI TCP Connection(5)-10.10.3.87] INFO
ServiceBusManager Stopping the WSO2 Enterprise Service Bus..
2008-06-09 10:55:49,007 [-] [RMI TCP Connection(5)-10.10.3.87] INFO
StatisticsReporterThread Statistics reporter thread is being stopped
2008-06-09 10:55:49,007 [-] [RMI TCP Connection(5)-10.10.3.87] INFO
RMIRegistryController Removing the RMI registy instance from the RMI
runtime
2008-06-09 10:55:49,013 [-] [RMI TCP Connection(5)-10.10.3.87] INFO
ServiceBusManager [ESB] Stop request completed
2008-06-09 10:55:49,013 [-] [RMI TCP Connection(5)-10.10.3.87] INFO
ServiceBusManager Graceful shutdown request completed in 0 seconds
2008-06-09 10:55:49,014 [-] [RMI TCP Connection(5)-10.10.3.87] INFO
ServiceBusManager Starting the WSO2 Enterprise Service Bus..
2008-06-09 10:55:49,015 [-] [RMI TCP Connection(5)-10.10.3.87] INFO
ServerManager Using Synapse home as :
/www/home/esbusadm/wso2_shared/wso2esb-1.7/.
2008-06-09 10:55:49,015 [-] [RMI TCP Connection(5)-10.10.3.87] INFO
ServerManager Using the Axis2 Repository :
/www/home/esbusadm/wso2_shared/wso2esb-1.7/./r
epository
2008-06-09 10:55:49,015 [-] [RMI TCP Connection(5)-10.10.3.87] INFO
ServerManager Using the axis2.xml :
/www/home/esbusadm/wso2_shared/wso2esb-1.7/./webapp/W
EB-INF/classes/conf/axis2.xml
2008-06-09 10:55:49,017 [-] [RMI TCP Connection(5)-10.10.3.87] INFO
ServerManager The server name was not specified, defaulting to :
app40.jamba.easynet.de
2008-06-09 10:55:49,017 [-] [RMI TCP Connection(5)-10.10.3.87] INFO
ServerManager The timeout handler will run every : 15s
2008-06-09 10:55:49,081 [-] [RMI TCP Connection(5)-10.10.3.87] INFO
SynapseInitializationModule Initializing Synapse at : Mon Jun 09
10:55:49 CEST 2008
2008-06-09 10:55:49,081 [10.10.3.87-app40.jamba.easynet.de] [RMI TCP
Connection(5)-10.10.3.87] INFO SynapseInitializationModule Loading
mediator extensions..
.
2008-06-09 10:55:49,229 [10.10.3.87-app40.jamba.easynet.de] [RMI TCP
Connection(5)-10.10.3.87] INFO SynapseInitializationModule Initializing
the Synapse conf
iguration ...
2008-06-09 10:55:49,230 [10.10.3.87-app40.jamba.easynet.de] [RMI TCP
Connection(5)-10.10.3.87] INFO DataSourceRegistrar DataSources will be
registered in the
JNDI context with provider PROP_URL : rmi://localhost:11815
2008-06-09 10:55:49,235 [10.10.3.87-app40.jamba.easynet.de] [RMI TCP
Connection(5)-10.10.3.87] INFO XMLConfigurationBuilder Generating the
Synapse configurat
[...]
interesting... in the statement above it seems as if the RMI-Provider
does not use the specified bind address. But back to the issue
[... skipped a few lines ...]
2008-06-09 10:55:49,269 [10.10.3.87-app40.jamba.easynet.de] [RMI TCP
Connection(5)-10.10.3.87] INFO HttpCoreNIOSender HTTPS Sender starting
2008-06-09 10:55:49,270 [10.10.3.87-app40.jamba.easynet.de] [RMI TCP
Connection(5)-10.10.3.87] INFO HttpCoreNIOSender HTTP Sender starting
2008-06-09 10:55:49,271 [10.10.3.87-app40.jamba.easynet.de] [RMI TCP
Connection(5)-10.10.3.87] INFO VFSTransportSender VFS Sender started
2008-06-09 10:55:49,278 [10.10.3.87-app40.jamba.easynet.de] [RMI TCP
Connection(5)-10.10.3.87] INFO JMSSender JMS Sender started
2008-06-09 10:55:49,388 [10.10.3.87-app40.jamba.easynet.de] [RMI TCP
Connection(5)-10.10.3.87] INFO ServerManager Starting transport https
on port 11812
2008-06-09 10:55:49,388 [10.10.3.87-app40.jamba.easynet.de] [RMI TCP
Connection(5)-10.10.3.87] INFO HttpCoreNIOSSLListener Loading Identity
Keystore from : w
ebapp/WEB-INF/classes/conf/identity.jks
2008-06-09 10:55:49,389 [10.10.3.87-app40.jamba.easynet.de] [RMI TCP
Connection(5)-10.10.3.87] INFO HttpCoreNIOSSLListener Loading Trust
Keystore from : weba
pp/WEB-INF/classes/conf/trust.jks
2008-06-09 10:55:49,391 [10.10.3.87-app40.jamba.easynet.de]
[HttpCoreNIOListener] WARN HttpCoreNIOListener System may be unstable:
IOReactor encountered a ch
ecked exception : Address already in use
java.net.BindException: Address already in use
at sun.nio.ch.Net.bind(Native Method)
at
sun.nio.ch.ServerSocketChannelImpl.bind(ServerSocketChannelImpl.java:119
)
at
sun.nio.ch.ServerSocketAdaptor.bind(ServerSocketAdaptor.java:59)
at
sun.nio.ch.ServerSocketAdaptor.bind(ServerSocketAdaptor.java:52)
at
org.apache.http.impl.nio.reactor.DefaultListeningIOReactor.processSessio
nRequests(DefaultListeningIOReactor.java:181)
at
org.apache.http.impl.nio.reactor.DefaultListeningIOReactor.processEvents
(DefaultListeningIOReactor.java:91)
at
org.apache.http.impl.nio.reactor.AbstractMultiworkerIOReactor.execute(Ab
stractMultiworkerIOReactor.java:160)
at
org.apache.synapse.transport.nhttp.HttpCoreNIOListener.startServerEngine
(HttpCoreNIOListener.java:125)
at
org.apache.synapse.transport.nhttp.HttpCoreNIOListener.access$200(HttpCo
reNIOListener.java:59)
at
org.apache.synapse.transport.nhttp.HttpCoreNIOListener$2.run(HttpCoreNIO
Listener.java:273)
at java.lang.Thread.run(Thread.java:595)
2008-06-09 10:55:49,392 [10.10.3.87-app40.jamba.easynet.de] [RMI TCP
Connection(5)-10.10.3.87] INFO HttpCoreNIOListener HTTPS Listener
starting on port : 118
12
2008-06-09 10:55:49,392 [10.10.3.87-app40.jamba.easynet.de] [RMI TCP
Connection(5)-10.10.3.87] INFO ServerManager Starting transport http on
port 11811
2008-06-09 10:55:49,393 [10.10.3.87-app40.jamba.easynet.de]
[HttpCoreNIOListener] WARN HttpCoreNIOListener System may be unstable:
IOReactor encountered a ch
ecked exception : Address already in use
java.net.BindException: Address already in use
at sun.nio.ch.Net.bind(Native Method)
at
sun.nio.ch.ServerSocketChannelImpl.bind(ServerSocketChannelImpl.java:119
)
at
sun.nio.ch.ServerSocketAdaptor.bind(ServerSocketAdaptor.java:59)
at
sun.nio.ch.ServerSocketAdaptor.bind(ServerSocketAdaptor.java:52)
at
org.apache.http.impl.nio.reactor.DefaultListeningIOReactor.processSessio
nRequests(DefaultListeningIOReactor.java:181)
at
org.apache.http.impl.nio.reactor.DefaultListeningIOReactor.processEvents
(DefaultListeningIOReactor.java:91)
at
org.apache.http.impl.nio.reactor.AbstractMultiworkerIOReactor.execute(Ab
stractMultiworkerIOReactor.java:160)
at
org.apache.synapse.transport.nhttp.HttpCoreNIOListener.startServerEngine
(HttpCoreNIOListener.java:125)
at
org.apache.synapse.transport.nhttp.HttpCoreNIOListener.access$200(HttpCo
reNIOListener.java:59)
at
org.apache.synapse.transport.nhttp.HttpCoreNIOListener$2.run(HttpCoreNIO
Listener.java:273)
at java.lang.Thread.run(Thread.java:595)
2008-06-09 10:55:49,394 [10.10.3.87-app40.jamba.easynet.de] [RMI TCP
Connection(5)-10.10.3.87] INFO HttpCoreNIOListener HTTP Listener
starting on address : a
pp40 port : 11811
2008-06-09 10:55:49,394 [10.10.3.87-app40.jamba.easynet.de] [RMI TCP
Connection(5)-10.10.3.87] INFO ServerManager Starting transport vfs
2008-06-09 10:55:49,401 [10.10.3.87-app40.jamba.easynet.de] [RMI TCP
Connection(5)-10.10.3.87] INFO VFSTransportListener VFS Listener
started
2008-06-09 10:55:49,401 [10.10.3.87-app40.jamba.easynet.de] [RMI TCP
Connection(5)-10.10.3.87] WARN VFSTransportListener Error configuring
the File/VFS trans
port for Service : los :: Cannot find parameter : transport.vfs.FileURI
for service : los
2008-06-09 10:55:49,401 [10.10.3.87-app40.jamba.easynet.de] [RMI TCP
Connection(5)-10.10.3.87] WARN VFSTransportListener Disabling the vfs
transport for the
service los, because it is not configured properly for the service
2008-06-09 10:55:49,402 [10.10.3.87-app40.jamba.easynet.de] [RMI TCP
Connection(5)-10.10.3.87] WARN VFSTransportListener Error configuring
the File/VFS trans
port for Service : pls :: Cannot find parameter : transport.vfs.FileURI
for service : pls
2008-06-09 10:55:49,402 [10.10.3.87-app40.jamba.easynet.de] [RMI TCP
Connection(5)-10.10.3.87] WARN VFSTransportListener Disabling the vfs
transport for the
service pls, because it is not configured properly for the service
2008-06-09 10:55:49,402 [10.10.3.87-app40.jamba.easynet.de] [RMI TCP
Connection(5)-10.10.3.87] INFO ServerManager Starting transport mailto
2008-06-09 10:55:49,402 [10.10.3.87-app40.jamba.easynet.de] [RMI TCP
Connection(5)-10.10.3.87] INFO MailTransportListener MAILTO Listener
started
2008-06-09 10:55:49,402 [10.10.3.87-app40.jamba.easynet.de] [RMI TCP
Connection(5)-10.10.3.87] WARN MailTransportListener Error configuring
the Mail transpor
t for Service : los :: Cannot find parameter : transport.mail.Address
for service : los
2008-06-09 10:55:49,403 [10.10.3.87-app40.jamba.easynet.de] [RMI TCP
Connection(5)-10.10.3.87] WARN MailTransportListener Disabling the
mailto transport for
the service los, because it is not configured properly for the service
2008-06-09 10:55:49,403 [10.10.3.87-app40.jamba.easynet.de] [RMI TCP
Connection(5)-10.10.3.87] WARN MailTransportListener Error configuring
the Mail transpor
t for Service : pls :: Cannot find parameter : transport.mail.Address
for service : pls
2008-06-09 10:55:49,403 [10.10.3.87-app40.jamba.easynet.de] [RMI TCP
Connection(5)-10.10.3.87] WARN MailTransportListener Disabling the
mailto transport for
the service pls, because it is not configured properly for the service
2008-06-09 10:55:49,403 [10.10.3.87-app40.jamba.easynet.de] [RMI TCP
Connection(5)-10.10.3.87] INFO ServerManager Starting transport
admin/https on port 11810
2008-06-09 10:55:49,403 [10.10.3.87-app40.jamba.easynet.de] [RMI TCP
Connection(5)-10.10.3.87] INFO ServerManager Ready for processing
2008-06-09 10:55:49,413 [10.10.3.87-app40.jamba.easynet.de] [RMI TCP
Connection(5)-10.10.3.87] INFO ServiceBusManager [ESB] Start request
completed
After this the server can't be accessed over the http transport listener
and needs to be restarted. This issue is reproducible in this
environment. We will check this in our test environment immediately.
Do you have any idea?
Regards,
Eric
_______________________________________________
Esb-java-dev mailing list
[email protected]
http://wso2.org/cgi-bin/mailman/listinfo/esb-java-dev
