On Apr 24, 2007, at 8:06 PM, Keith Babo wrote:
>
> Kedar -
>
> I agree that the shutdown during startup message is confusing.
> This is a side effect of the way we currently handle XA recovery
> processing during startup. We just integrated a fix in this area
> today, so you should not see any more "shutting down ..." messages
> during startup.
>
> Jerome -
>
> As a general logging strategy, it seems to me like the JBI
> framework is doing the right thing here. The framework is issuing
> an INFO level log entry when it starts a component container.
> Won't v3 do the same when it loads containers/modules on-demand in
> response to a deployment (e.g. start the PHP container when a PHP
> app is deployed)?
>
Right, one is ok once you start using the container (ie the first JBI
application is started), however 4 is clearly too many but you
already agreed to that above so I think we are in agreement.
Regards, Jerome
> regards,
> keith
>
> Jerome Dochez wrote:
>> 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,
>>>>>>>>> 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)
>>>
>>> --------------------------------------------------------------------
>>> -
>>> 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
>
> --
> Sun's Open ESB Community (http://open-esb.org)
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: dev-unsubscribe_at_glassfish.dev.java.net
> For additional commands, e-mail: dev-help_at_glassfish.dev.java.net
>