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
>