dev@glassfish.java.net

Re: Why is JBI stopping and then starting on server startup ...

From: Mark S White <Mark.White_at_Sun.COM>
Date: Tue, 24 Apr 2007 14:40:26 -0700

I was under the impression that WARNING or SEVERE messages were used to
indicate
a problem, and the INFO messages were merely to show normal operations.
I was not
aware that an INFO message should be used to indicate that there is a
problem.

kedar wrote:
> Let me retry.
>
> It is bad to have too many generic messages in the server log at
> default log level.
> But it is usually at the developer's discretion to log a message at a
> level. Several
> messages are generic, in that they don't necessarily raise
> user/administrator's eye brows.
>
> This particular message that came during startup certainly catches an
> eye. You have
> to make an extra effort to convey the users that it is normal. If we
> have too many
> such messages that turn out to be "normal" because of release notes,
> documentation
> or pure experience, it just means that we are not logging things right.
>
> Again, this is not nit picking. A shutdown-like message during startup
> *actually*
> made me think whether all was well and prompted me to write this message.
>
>
> Mark S White wrote:
>> 2. The code that starts/stops components is unaware of whether it is
>> being called during
>> startup of the server. I'm not sure it's worth someone spending a lot
>> of time changing a
>> good bit of code to eliminate 2-3 messages at startup.
>>
>> kedar wrote:
>>> 1- We should fix it with other components (In fact, I am fixing one
>>> such useless message myself). There is no pointing out a single
>>> component. I agree, the llllllllong JMSRA message is just annoying.
>>>
>>> 2- I am not convinced that *at the startup of the server* users need
>>> to see that binding components are stopped and are restarted. It is
>>> OK to say that they are "started".
>>>
>>>
>>> Mark S White wrote:
>>>> The frequency of starting/stopping a component is going to be quite
>>>> low. We do believe this
>>>> message warrants being logged at the INFO level. If we don't log
>>>> these messages, then it would
>>>> be very difficult to troubleshoot a problem related to component
>>>> states, because we wouldn't
>>>> have any indication in the log about when a component was
>>>> started/stopped.
>>>>
>>>> Remember a component is effectively a container. Not logging
>>>> anything when a component is
>>>> stopped or started would be analogous to not logging anything when
>>>> a web container or EJB
>>>> container is stopped or started.
>>>>
>>>> I see a lot more clutter in server.log at the INFO level from other
>>>> areas, such as this:
>>>>
>>>> [#|2007-04-24T11:22:03.484-0700|INFO|sun-appserver9.1|javax.resourceadapter.mqjmsra.lifecycle|_ThreadID=10;_ThreadName=main;|MQJMSRA_EB1101:
>>>> run:EMBEDDED broker started with code =0|#]
>>>>
>>>> [#|2007-04-24T11:22:03.640-0700|INFO|sun-appserver9.1|javax.resourceadapter.mqjmsra.lifecycle|_ThreadID=10;_ThreadName=main;|MQJMSRA_RA1101:
>>>> SJSMQ JMS ResourceAdaapter configuration=
>>>> raUID =null
>>>> brokerType =EMBEDDED
>>>> brokerInstanceName =imqbroker
>>>> brokerBindAddress =null
>>>> brokerPort =9099
>>>> brokerHomeDir
>>>> =C:/d/open2/open-esb/install/as8\imq\bin\..
>>>> brokerVarDir
>>>> =C:/d/open2/open-esb/install/as8/domains/domain1\imq
>>>> brokerJavaDir =c:/Java/jdk1.5.0_09
>>>> brokerArgs =null
>>>> brokerStartTimeout =60000
>>>> adminUsername =admin
>>>> adminPassFile =C:\d\tmp\asmq7703.tmp
>>>> useJNDIRmiServiceURL =true
>>>> rmiRegistryPort =8886
>>>> startRmiRegistry =false
>>>> useSSLJMXConnector =true
>>>> brokerEnableHA =false
>>>> clusterId =null
>>>> brokerId =null
>>>> jmxServiceURL =null
>>>> dbType =null
>>>> dbProps ={}
>>>> dsProps ={}
>>>> ConnectionURL =
>>>> UserName =guest
>>>> ReconnectEnabled =true
>>>> ReconnectInterval =5000
>>>> ReconnectAttempts =3
>>>> AddressListBehavior =RANDOM
>>>> AddressListIterations =3
>>>> InAppClientContainer =false
>>>> InClusteredContainer =false
>>>> GroupName =null
>>>> |#]
>>>>
>>>> [#|2007-04-24T11:22:03.640-0700|INFO|sun-appserver9.1|javax.resourceadapter.mqjmsra.lifecycle|_ThreadID=10;_ThreadName=main;|MQJMSRA_RA1101:
>>>> start:SJSMQ JMSRA Connection Factory
>>>> Config={imqOverrideJMSPriority=false, imqConsumerFlowLimit=1000,
>>>> imqOverrideJMSExpiration=false, imqAddressListIterations=3,
>>>> imqLoadMaxToServerSession=true, imqConnectionType=TCP,
>>>> imqPingInterval=30, imqSetJMSXUserID=false, imqConfiguredClientID=,
>>>> imqSSLProviderClassname=com.sun.net.ssl.internal.ssl.Provider,
>>>> imqJMSDeliveryMode=PERSISTENT, imqConnectionFlowLimit=1000,
>>>> imqConnectionURL=http://localhost/imq/tunnel,
>>>> imqBrokerServiceName=, imqJMSPriority=4,
>>>> imqBrokerHostName=localhost, imqJMSExpiration=0, imqAckOnProduce=,
>>>> imqEnableSharedClientID=false, imqAckTimeout=0,
>>>> imqAckOnAcknowledge=, imqConsumerFlowThreshold=50,
>>>> imqDefaultPassword=guest,
>>>> imqQueueBrowserMaxMessagesPerRetrieve=1000,
>>>> imqDefaultUsername=guest, imqReconnectEnabled=false,
>>>> imqConnectionFlowCount=100, imqAddressListBehavior=PRIORITY,
>>>> imqReconnectAttempts=3, imqSetJMSXAppID=false,
>>>> imqConnectionHandler=com.sun.messaging.jmq.jmsclient.protocol.tcp.TCPStreamHandler,
>>>> imqSetJMSXRcvTimestamp=false, imqBrokerServicePort=0,
>>>> imqDisableSetClientID=false, imqSetJMSXConsumerTXID=false,
>>>> imqOverrideJMSDeliveryMode=false, imqBrokerHostPort=7676,
>>>> imqQueueBrowserRetrieveTimeout=60000, imqSetJMSXProducerTXID=false,
>>>> imqSSLIsHostTrusted=false, imqConnectionFlowLimitEnabled=false,
>>>> imqReconnectInterval=5000, imqAddressList=localhost:9099,
>>>> imqOverrideJMSHeadersToTemporaryDestinations=false}|#]
>>>>
>>>> [#|2007-04-24T11:22:03.640-0700|INFO|sun-appserver9.1|javax.resourceadapter.mqjmsra.lifecycle|_ThreadID=10;_ThreadName=main;|MQJMSRA_RA1101:
>>>> SJSMQ JMSRA Started|#]
>>>>
>>>> kedar wrote:
>>>>> Thank you, Mark.
>>>>>
>>>>> Is it required that the user sees that the binding components
>>>>> are being restarted? Is this log record required to be at the
>>>>> default ("INFO") log level?
>>>>>
>>>>> Kedar
>>>>>
>>>>> Mark S White wrote:
>>>>>> JBI is not stopping and starting up. What you are seeing is that
>>>>>> once a deployment has been
>>>>>> made to a component (such as the Java EE engine or the HTTP
>>>>>> binding), whenever the
>>>>>> system restarts, the component must be initialized in order to
>>>>>> inform it of the existing deployments.
>>>>>> This is required by the JSR208 specification, as components are
>>>>>> not required to persist any
>>>>>> deployment information. In the case you are seeing, the
>>>>>> components had a desired state of
>>>>>> shutdown, so after the initialization was done, JBI has shut down
>>>>>> the components to return
>>>>>> them to their desired states. JBI itself did not stop, it only
>>>>>> started. The component shutdowns
>>>>>> were part of the startup processing.
>>>>>>
>>>>>> kedar wrote:
>>>>>>> More often than not, upon server startup, I see messages like:
>>>>>>>
>>>>>>> [#|2007-04-24T11:08:11.503-0700|INFO|sun-appserver9.1|javax.enterprise.system.core|_ThreadID=10;_ThreadName=main;|Application
>>>>>>> server startup complete.|#]
>>>>>>>
>>>>>>> [#|2007-04-24T11:21:38.233-0700|INFO|sun-appserver9.1|com.sun.jbi.framework|_ThreadID=17;_ThreadName=sun-javaee-engine;|JBIFW1166:
>>>>>>> Engine sun-javaee-engine has been shut down.|#]
>>>>>>>
>>>>>>> [#|2007-04-24T11:21:38.236-0700|INFO|sun-appserver9.1|sun-http-binding.com.sun.jbi.httpsoapbc.HttpSoapBindingLifeCycle|_ThreadID=18;_ThreadName=sun-http-binding;|HTTP
>>>>>>> SOAP binding shutdown completed.|#]
>>>>>>>
>>>>>>> [#|2007-04-24T11:21:38.236-0700|INFO|sun-appserver9.1|com.sun.jbi.framework|_ThreadID=18;_ThreadName=sun-http-binding;|JBIFW1166:
>>>>>>> Binding sun-http-binding has been shut down.|#]
>>>>>>>
>>>>>>> [#|2007-04-24T11:21:38.238-0700|INFO|sun-appserver9.1|com.sun.jbi.framework|_ThreadID=16;_ThreadName=httpSSLWorkerThread-4848-0;|JBIFW0012:
>>>>>>> JBI framework startup complete.|#]
>>>>>>>
>>>>>>>
>>>>>>> Why is JBI stopping and then starting up?
>>>>>>>
>>>>>>> Thanks,
>>>>>>> Kedar
>>>>>>>
>>>>>>> ---------------------------------------------------------------------
>>>>>>>
>>>>>>> To unsubscribe, e-mail: dev-unsubscribe_at_glassfish.dev.java.net
>>>>>>> For additional commands, e-mail: dev-help_at_glassfish.dev.java.net
>>>>>>>
>>>>>>
>>>>>
>>>>> ---------------------------------------------------------------------
>>>>> To unsubscribe, e-mail: dev-unsubscribe_at_glassfish.dev.java.net
>>>>> For additional commands, e-mail: dev-help_at_glassfish.dev.java.net
>>>>>
>>>>
>>>
>>> ---------------------------------------------------------------------
>>> To unsubscribe, e-mail: dev-unsubscribe_at_glassfish.dev.java.net
>>> For additional commands, e-mail: dev-help_at_glassfish.dev.java.net
>>>
>>
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: dev-unsubscribe_at_glassfish.dev.java.net
> For additional commands, e-mail: dev-help_at_glassfish.dev.java.net
>

-- 
Open ESB Community (http://open-esb.org)
Check out my blog (http://blogs.sun.com/mwhite)