[wildfly-dev] Misleading error message on extension add failure

Wed May 8 11:18:11 EDT 2013

On 5/8/13 9:15 AM, Bartosz Baranowski wrote:
>
>
> ----- Original Message -----
>> From: "Brian Stansberry" <brian.stansberry at redhat.com>
>> To: wildfly-dev at lists.jboss.org
>> Sent: Wednesday, May 8, 2013 4:01:20 PM
>> Subject: Re: [wildfly-dev] Misleading error message on extension add failure
>>
>> 1. This is because it is a post-boot error that did not affect the
>> runtime and thus hasn't had any negative effect on the operation of the
>> process. A post-boot management operation has a caller; the failure
>> response is sent to the caller to deal with. The caller should be
>> looking at the response, not the log.
>>
>> The rationale for this is analogous to not logging an ERROR for every
>> EJB invocation failure.
>>
>> 2. This is because the detail information might be useful, so we do log it.
> +1, I dont deny this. I would make this a "WARN" not "DEBUG" - since its not a "failed EJB invocation" - it is a parse/model change failure.

I disagree with a general statement that we should always log model 
change failures at WARN. But, this specific case can be handled better:

https://github.com/wildfly/wildfly/pull/4478

Thanks for raising this issue!

Re: the general statement:

It's not a parse failure; parsing is done at boot and if it had failed 
at boot it would have been logged at ERROR.

It is a model change failure, but those aren't logged higher than DEBUG 
post-boot because many, many such failures are simple user mistakes 
(typos, invalid values and such) that are reported to the client on the 
client side. Putting WARN and ERROR messages in the logs for such things 
can generate a lot of unnecessary alarm bells. The patch ^^^ does a 
better job of distinguishing the "user mistake" case from the "internal 
problem" case.

>>
>> 3. This is a mistake in ExtensionAddHandler L103 -- when it creates the
>> OperationFailedException it should pass the cause into the constructor.
>>
> Roger.
>> On 5/8/13 3:18 AM, Bartosz Baranowski wrote:
>>>
>>> Im not sure what is a general policy about logging such things but... it
>>> seems odd. If Im wrong, please ignore.
>>>
>>> Ive been playing with extension test cases and here is what I found out:
>>>
>>> 1. If Extension Add handler fails, no error/warn message is displayed.
>>> 2. Above is false IF level is set to debug:
>>>
>>> :59,685 DEBUG org.jboss.as.controller.management-operation JBAS014616:
>>> Operation ("add") failed - address: ([("extension" => "jmxrmiconnector")])
>>> - failure description: "org.jboss.modules.ModuleLoadException: Error
>>> loading module from
>>> /home/baranowb/redhat/git/jboss-as/testsuite/integration/basic/../../../build/target/wildfly-8.0.0.Alpha1-SNAPSHOT/modules/jmxrmiconnector/main/module.xml"
>>>
>>> 3. Above message is cryptic at best - "Error loading module" - what error,
>>> where, why?
>>>
>>> Full stack trace for #2
>>>
>>> 15:06:26,373 ERROR stderr org.jboss.modules.ModuleLoadException: Error
>>> loading module from
>>> /home/baranowb/redhat/git/jboss-as/testsuite/integration/basic/../../../build/target/wildfly-8.0.0.Alpha1-SNAPSHOT/modules/jmxrmiconnector/main/module.xml
>>> 15:06:26,373 ERROR stderr at
>>> org.jboss.modules.ModuleXmlParser.parseModuleXml(ModuleXmlParser.java:292)
>>> 15:06:26,374 ERROR stderr at
>>> org.jboss.modules.ModuleXmlParser.parseModuleXml(ModuleXmlParser.java:256)
>>> 15:06:26,374 ERROR stderr at
>>> org.jboss.modules.LocalModuleFinder$1.run(LocalModuleFinder.java:144)
>>> 15:06:26,374 ERROR stderr at
>>> org.jboss.modules.LocalModuleFinder$1.run(LocalModuleFinder.java:138)
>>> 15:06:26,374 ERROR stderr at
>>> java.security.AccessController.doPrivileged(Native Method)
>>> 15:06:26,375 ERROR stderr at
>>> org.jboss.modules.LocalModuleFinder.findModule(LocalModuleFinder.java:138)
>>> 15:06:26,375 ERROR stderr at
>>> org.jboss.modules.ModuleLoader.findModule(ModuleLoader.java:389)
>>> 15:06:26,375 ERROR stderr at
>>> org.jboss.modules.ModuleLoader.loadModuleLocal(ModuleLoader.java:293)
>>> 15:06:26,376 ERROR stderr at
>>> org.jboss.modules.ModuleLoader.preloadModule(ModuleLoader.java:240)
>>> 15:06:26,376 ERROR stderr at
>>> org.jboss.modules.ModuleLoader.loadModule(ModuleLoader.java:222)
>>> 15:06:26,376 ERROR stderr at
>>> org.jboss.modules.Module.loadServiceFromCallerModuleLoader(Module.java:322)
>>> 15:06:26,377 ERROR stderr at
>>> org.jboss.as.controller.extension.ExtensionAddHandler.initializeExtension(ExtensionAddHandler.java:84)
>>> 15:06:26,377 ERROR stderr at
>>> org.jboss.as.controller.extension.ExtensionAddHandler.execute(ExtensionAddHandler.java:70)
>>> 15:06:26,378 ERROR stderr at
>>> org.jboss.as.controller.AbstractOperationContext.executeStep(AbstractOperationContext.java:439)
>>> 15:06:26,378 ERROR stderr at
>>> org.jboss.as.controller.AbstractOperationContext.doCompleteStep(AbstractOperationContext.java:321)
>>> 15:06:26,379 ERROR stderr at
>>> org.jboss.as.controller.AbstractOperationContext.completeStepInternal(AbstractOperationContext.java:228)
>>> 15:06:26,380 ERROR stderr at
>>> org.jboss.as.controller.AbstractOperationContext.executeOperation(AbstractOperationContext.java:223)
>>> 15:06:26,380 ERROR stderr at
>>> org.jboss.as.controller.ModelControllerImpl.internalExecute(ModelControllerImpl.java:235)
>>> 15:06:26,381 ERROR stderr at
>>> org.jboss.as.controller.ModelControllerImpl.execute(ModelControllerImpl.java:124)
>>> 15:06:26,381 ERROR stderr at
>>> org.jboss.as.controller.remote.ModelControllerClientOperationHandler$ExecuteRequestHandler.doExecute(ModelControllerClientOperationHandler.java:148)
>>> 15:06:26,382 ERROR stderr at
>>> org.jboss.as.controller.remote.ModelControllerClientOperationHandler$ExecuteRequestHandler.access$300(ModelControllerClientOperationHandler.java:97)
>>> 15:06:26,382 ERROR stderr at
>>> org.jboss.as.controller.remote.ModelControllerClientOperationHandler$ExecuteRequestHandler$1.execute(ModelControllerClientOperationHandler.java:114)
>>> 15:06:26,382 ERROR stderr at
>>> org.jboss.as.protocol.mgmt.AbstractMessageHandler$2$1.doExecute(AbstractMessageHandler.java:296)
>>> 15:06:26,383 ERROR stderr at
>>> org.jboss.as.protocol.mgmt.AbstractMessageHandler$AsyncTaskRunner.run(AbstractMessageHandler.java:518)
>>> 15:06:26,383 ERROR stderr at
>>> java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
>>> 15:06:26,383 ERROR stderr at
>>> java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
>>> 15:06:26,384 ERROR stderr at java.lang.Thread.run(Thread.java:722)
>>> 15:06:26,384 ERROR stderr at
>>> org.jboss.threads.JBossThread.run(JBossThread.java:122)
>>> 15:06:26,385 ERROR stderr Caused by: javax.xml.stream.XMLStreamException:
>>> ParseError at [row,col]:[21,52]
>>> 15:06:26,385 ERROR stderr Message: Failed to add resource root
>>> 'service-loader-resources' at path 'service-loader-resources'
>>> 15:06:26,385 ERROR stderr at
>>> org.jboss.modules.ModuleXmlParser.parseResourceRoot(ModuleXmlParser.java:756)
>>> 15:06:26,386 ERROR stderr at
>>> org.jboss.modules.ModuleXmlParser.parseResources(ModuleXmlParser.java:712)
>>> 15:06:26,386 ERROR stderr at
>>> org.jboss.modules.ModuleXmlParser.parseModuleContents(ModuleXmlParser.java:538)
>>> 15:06:26,386 ERROR stderr at
>>> org.jboss.modules.ModuleXmlParser.parseDocument(ModuleXmlParser.java:369)
>>> 15:06:26,387 ERROR stderr at
>>> org.jboss.modules.ModuleXmlParser.parseModuleXml(ModuleXmlParser.java:287)
>>> 15:06:26,387 ERROR stderr ... 27 more
>>>
>>>
>>>
>>> Here is link to commit:
>>> https://github.com/wildfly/wildfly/commit/3973d7cd2edcf913461dc65902ff471689452bb7#commitcomment-3131977
>>> _______________________________________________
>>> wildfly-dev mailing list
>>> wildfly-dev at lists.jboss.org
>>> https://lists.jboss.org/mailman/listinfo/wildfly-dev
>>>
>>
>>
>> --
>> Brian Stansberry
>> Principal Software Engineer
>> JBoss by Red Hat
>> _______________________________________________
>> wildfly-dev mailing list
>> wildfly-dev at lists.jboss.org
>> https://lists.jboss.org/mailman/listinfo/wildfly-dev
>>

-- 
Brian Stansberry
Principal Software Engineer
JBoss by Red Hat