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 15:35:25 -0700

So you're saying that we shouldn't even log a message that says "JBI
framework started"?
We shouldn't be logging anything at all during normal execution?

Jerome Dochez wrote:
> This is right, however a normal run of a particular technology should
> not produce any message. For instance, deployment has tendencies of
> being too verbose, same here, if this type of message relate to normal
> function of your runtime, just don't say it. INFO should be used for
> information that is not an error yet denotes something different in
> your runtime environment.
>
> As pointed below, JMS is notoriously abusing the INFO level, while it
> should really use FINE for this type of logs.
>
> Jerome
>
> On Apr 24, 2007, at 2:40 PM, Mark S White wrote:
>
>> 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)
>>
>> ---------------------------------------------------------------------
>> 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)