dev@glassfish.java.net

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

From: Jerome Dochez <Jerome.Dochez_at_Sun.COM>
Date: Tue, 24 Apr 2007 16:58:24 -0700

when embedded in GF, that's exactly what I am saying. now, we can
tolerate one message of course, but i seem the see at least 4 in the
log that started the thread. 4 messages for something that you said
was normal operational behaviour seems too many.


On Apr 24, 2007, at 3:35 PM, Mark S White wrote:

> 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, i
>>>>>>> mqJMSDeliveryMode=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.tc
>>>>>>> p.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)
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: dev-unsubscribe_at_glassfish.dev.java.net
> For additional commands, e-mail: dev-help_at_glassfish.dev.java.net
>