Logging verbosity

Heiko W.Rupp hrupp at redhat.com
Thu Dec 19 09:33:22 UTC 2013


Am 18.12.2013 um 00:17 schrieb Lukas Krejci <lkrejci at redhat.com>:

> I'm not sure I can agree with that..
> 
> Customer: We have this issue, our server doesn't work.
> Support: What does the log say?
> Customer: [ERROR] - Failed to collect important stuff because of: null (this 
> is just to exacerbate the change in logging I started this thread with).
> Support: Oh, could you please go back to your server and replicate the issue 
> with debug logging on? We need to see the stacktraces.
> Customer: You mean reconfiguring a production server? Why didn't include 
> enough info in the message so that you can diagnose the error?
> 
> Or a slightly different conversation:
> ... start off the same as above ...
> Support: We can't diagnose the issue unless we send you a diagnostic patch.
> Customer: What kind of muppets are you, seriously?
> 
> What you say is correct, but not sufficient IMHO - the information the log 
> message provides should be digestable by non-developers. But at the same time,  
> it should also provide the developer with enough info to diagnose the 
> underlying issue. And the more severe the log message is, the more it applies. 

So I just got this trace below ~100 times in the logs (tests after code modification):
That stack trace(s) shows me a 100 times where such a rejected execution has happened, but not the
cause -- that cause is in the 1st line "Failed to stop.. ".
It may be interesting to see that this execution failed in
	at org.rhq.core.pc.inventory.ResourceContainer$ResourceComponentInvocationHandler.invokeInNewThreadWithLock(ResourceContainer.java:639)
	at org.rhq.core.pc.inventory.ResourceContainer$ResourceComponentInvocationHandler.invoke(ResourceContainer.java:629)

But that is all -- every other line in the log is just confusing to everyone.

What I really would like to see in the log is the real cause (why was the component not stopped? E.g. because
of an exception or because it was never started.). But this one is just plain useless and distracts from the 
real information.


10:25:57,671 WARN  [main] (rhq.core.pc.inventory.InventoryManager) - Plugin Error: Failed to stop component for [Resource[id=3, uuid=06df1776-9e99-4bd2-9403-14f6f726d0f8, type={availPlugin}AvailParentServer1, key=AvailParentServer1_1, name=AvailParentServer1_1, parent=testplatform, version=1]].
java.util.concurrent.RejectedExecutionException: Task java.util.concurrent.FutureTask at 632117dc rejected from java.util.concurrent.ThreadPoolExecutor at 3ae948c3[Terminated, pool size = 0, active threads = 0, queued tasks = 0, completed tasks = 2]
	at java.util.concurrent.ThreadPoolExecutor$AbortPolicy.rejectedExecution(ThreadPoolExecutor.java:2048)
	at java.util.concurrent.ThreadPoolExecutor.reject(ThreadPoolExecutor.java:821)
	at java.util.concurrent.ThreadPoolExecutor.execute(ThreadPoolExecutor.java:1372)
	at java.util.concurrent.AbstractExecutorService.submit(AbstractExecutorService.java:132)
	at org.rhq.core.pc.inventory.ResourceContainer$ResourceComponentInvocationHandler.invokeInNewThreadWithLock(ResourceContainer.java:639)
	at org.rhq.core.pc.inventory.ResourceContainer$ResourceComponentInvocationHandler.invoke(ResourceContainer.java:629)
	at com.sun.proxy.$Proxy23.stop(Unknown Source)
	at org.rhq.core.pc.inventory.InventoryManager.deactivateResource(InventoryManager.java:2207)
	at org.rhq.core.pc.inventory.InventoryManager.deactivateResource(InventoryManager.java:2201)
	at org.rhq.core.pc.inventory.InventoryManager.persistToDisk(InventoryManager.java:2229)
	at org.rhq.core.pc.inventory.InventoryManager.shutdown(InventoryManager.java:295)
	at org.rhq.core.pc.PluginContainer.shutdown(PluginContainer.java:401)
	at org.rhq.test.arquillian.impl.RhqAgentPluginContainer.stopPc(RhqAgentPluginContainer.java:384)
	at org.rhq.test.arquillian.impl.RhqAgentPluginContainer.stop(RhqAgentPluginContainer.java:203)
	at org.jboss.arquillian.container.impl.ContainerImpl.stop(ContainerImpl.java:217)
	at org.jboss.arquillian.container.impl.client.container.ContainerLifecycleController$9.perform(ContainerLifecycleController.java:178)
	at org.jboss.arquillian.container.impl.client.container.ContainerLifecycleController$9.perform(ContainerLifecycleController.java:172)
	at org.jboss.arquillian.container.impl.client.container.ContainerLifecycleController.forContainer(ContainerLifecycleController.java:255)
	at org.jboss.arquillian.container.impl.client.container.ContainerLifecycleController.stopContainer(ContainerLifecycleController.java:171)
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.lang.reflect.Method.invoke(Method.java:606)
	at org.jboss.arquillian.core.impl.ObserverImpl.invoke(ObserverImpl.java:94)
	at org.jboss.arquillian.core.impl.EventContextImpl.invokeObservers(EventContextImpl.java:99)
	at org.jboss.arquillian.core.impl.EventContextImpl.proceed(EventContextImpl.java:81)
	at org.jboss.arquillian.container.impl.client.ContainerDeploymentContextHandler.createContainerContext(ContainerDeploymentContextHandler.java:57)
	at sun.reflect.GeneratedMethodAccessor35.invoke(Unknown Source)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.lang.reflect.Method.invoke(Method.java:606)
	at org.jboss.arquillian.core.impl.ObserverImpl.invoke(ObserverImpl.java:94)
	at org.jboss.arquillian.core.impl.EventContextImpl.proceed(EventContextImpl.java:88)
	at org.jboss.arquillian.core.impl.ManagerImpl.fire(ManagerImpl.java:135)
	at org.jboss.arquillian.core.impl.ManagerImpl.fire(ManagerImpl.java:115)
	at org.jboss.arquillian.core.impl.EventImpl.fire(EventImpl.java:67)
	at org.jboss.arquillian.container.impl.client.container.ContainerLifecycleController$4.perform(ContainerLifecycleController.java:107)
	at org.jboss.arquillian.container.impl.client.container.ContainerLifecycleController$4.perform(ContainerLifecycleController.java:100)
	at org.jboss.arquillian.container.impl.client.container.ContainerLifecycleController.forEachSuiteContainer(ContainerLifecycleController.java:221)
	at org.jboss.arquillian.container.impl.client.container.ContainerLifecycleController.stopSuiteContainers(ContainerLifecycleController.java:99)
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.lang.reflect.Method.invoke(Method.java:606)
	at org.jboss.arquillian.core.impl.ObserverImpl.invoke(ObserverImpl.java:94)
	at org.jboss.arquillian.core.impl.EventContextImpl.invokeObservers(EventContextImpl.java:99)
	at org.jboss.arquillian.core.impl.EventContextImpl.proceed(EventContextImpl.java:81)
	at org.jboss.arquillian.core.impl.ManagerImpl.fire(ManagerImpl.java:135)
	at org.jboss.arquillian.core.impl.ManagerImpl.fire(ManagerImpl.java:115)
	at org.jboss.arquillian.core.impl.EventImpl.fire(EventImpl.java:67)
	at org.jboss.arquillian.container.test.impl.client.ContainerEventController.execute(ContainerEventController.java:91)
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.lang.reflect.Method.invoke(Method.java:606)
	at org.jboss.arquillian.core.impl.ObserverImpl.invoke(ObserverImpl.java:94)
	at org.jboss.arquillian.core.impl.EventContextImpl.invokeObservers(EventContextImpl.java:99)
	at org.jboss.arquillian.core.impl.EventContextImpl.proceed(EventContextImpl.java:81)
	at org.jboss.arquillian.test.impl.TestContextHandler.createSuiteContext(TestContextHandler.java:60)
	at sun.reflect.GeneratedMethodAccessor30.invoke(Unknown Source)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.lang.reflect.Method.invoke(Method.java:606)
	at org.jboss.arquillian.core.impl.ObserverImpl.invoke(ObserverImpl.java:94)
	at org.jboss.arquillian.core.impl.EventContextImpl.proceed(EventContextImpl.java:88)
	at org.jboss.arquillian.core.impl.ManagerImpl.fire(ManagerImpl.java:135)
	at org.jboss.arquillian.core.impl.ManagerImpl.fire(ManagerImpl.java:115)
	at org.jboss.arquillian.test.impl.EventTestRunnerAdaptor.afterSuite(EventTestRunnerAdaptor.java:73)
	at org.jboss.arquillian.testng.Arquillian.arquillianAfterSuite(Arquillian.java:90)
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.lang.reflect.Method.invoke(Method.java:606)
	at org.testng.internal.MethodInvocationHelper.invokeMethod(MethodInvocationHelper.java:80)
	at org.testng.internal.Invoker.invokeConfigurationMethod(Invoker.java:551)
	at org.testng.internal.Invoker.invokeConfigurations(Invoker.java:213)
	at org.testng.internal.Invoker.invokeConfigurations(Invoker.java:138)
	at org.testng.SuiteRunner.privateRun(SuiteRunner.java:308)
	at org.testng.SuiteRunner.run(SuiteRunner.java:240)
	at org.testng.SuiteRunnerWorker.runSuite(SuiteRunnerWorker.java:53)
	at org.testng.SuiteRunnerWorker.run(SuiteRunnerWorker.java:87)
	at org.testng.TestNG.runSuitesSequentially(TestNG.java:1188)
	at org.testng.TestNG.runSuitesLocally(TestNG.java:1113)
	at org.testng.TestNG.run(TestNG.java:1025)
	at org.apache.maven.surefire.testng.TestNGExecutor.run(TestNGExecutor.java:77)
	at org.apache.maven.surefire.testng.TestNGDirectoryTestSuite.executeMulti(TestNGDirectoryTestSuite.java:159)
	at org.apache.maven.surefire.testng.TestNGDirectoryTestSuite.execute(TestNGDirectoryTestSuite.java:99)
	at org.apache.maven.surefire.testng.TestNGProvider.invoke(TestNGProvider.java:106)
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.lang.reflect.Method.invoke(Method.java:606)
	at org.apache.maven.surefire.util.ReflectionUtils.invokeMethodWithArray(ReflectionUtils.java:189)
	at org.apache.maven.surefire.booter.ProviderFactory$ProviderProxy.invoke(ProviderFactory.java:165)
	at org.apache.maven.surefire.booter.ProviderFactory.invokeProvider(ProviderFactory.java:85)
	at org.apache.maven.surefire.booter.ForkedBooter.runSuitesInProcess(ForkedBooter.java:115)
	at org.apache.maven.surefire.booter.ForkedBooter.main(ForkedBooter.java:75)


More information about the rhq-devel mailing list