dev@glassfish.java.net

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

From: Sivakumar Thyagarajan <Sivakumar.Thyagarajan_at_Sun.COM>
Date: Wed, 25 Apr 2007 23:15:47 +0530

> As pointed below, JMS is notoriously abusing the INFO level, while it
> should really use FINE for this type of logs.

Thanks Jerome and Mark for pointing this out. There has been an issue
already filed to fix this and we are working with the OpenMQ team to fix this.

https://glassfish.dev.java.net/issues/show_bug.cgi?id=1782

Thanks
--Siva.

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
>