[jboss-jira] [JBoss JIRA] (WFCORE-2351) There stuck some required service after unsuccessful command for adding CredentialStore with wrong filled relative-to attribute.

[Brian Stansberry (JIRA)]

    [ https://issues.jboss.org/browse/WFCORE-2351?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13380482#comment-13380482 ] 

Brian Stansberry commented on WFCORE-2351:
------------------------------------------

[~soul2zimate] I think the fix is something different, although you are on the right track regarding checking if a service controller is still installed.

Here's what's going on:

AbstractOperationContext.processStages() before going to Stage.VERIFY calls awaitServiceContainerStability() which eventually calls ContainerStateMonitor.createContainerStateChangeReport(false). *Nothing is logged at this point* (which is deliberate), but the internal fields in ContainerStateMonitor get populated with some data.

The logging at 16:54:18,810 comes from ContainerStateMonitor.logContainerStateChangesAndReset() which indirectly is called by OperationContextImpl.Step.releaseStepLocks. This is called when the operation is completing. In this case the op has rolled back, and therefore there is no unsatisfied dependency any more! But the logging at 16:54:18,810 is as if the rollback hasn't occurred.

Then the next op comes along, and when it completes and reaches OperationContextImpl.Step.releaseStepLocks, that's when another report is generated that reports the "correction" that actually occurred during the rollback of the previous op.

The reason you get a report after the second op is ContainerStateMonitor is not left in the correct state after the first op completes. ContainerStateMonitor.previousMissingDepSet should be empty at that point.

The cause of that not being empty is that when ContainerStateMonitor.createContainerStateChangeReport is called the 2nd time in the first op, the time that produces logging, it uses the 'failed' and 'problems' sets. But those sets can contain ServiceControllers that were added over the course of execution of the op, but which are no longer installed (because the op rolled back). If they are no longer installed, they are no longer "problems" or "failed" so they should be ignored when creating the report.

https://github.com/wildfly/wildfly-core/compare/master...bstansberry:WFCORE-2351 does that (sorry; I kind of hide the key change behind some refactoring to use Collections.emptySet/Map where possible.)  Doing that makes the bogus report after the 2nd op go away.

A problem is it makes the first report at 16:54:18,810 go away as well. Perhaps that's good! Quite a few people dislike those messages; they can be quite noisy. And if the end result of the operation is that MSC has no failed services or missing dependencies, then there's nothing to report.

But I'm a bit reluctant to just drop that first report. I could restore it by having the call from AbstractOperationContext.processStages() result in logging, and then the OperationContextImpl.Step.releaseStepLocks call also logs, but now reporting the "no longer missing" services. So basically the 2 log statements shown in the description, but now the 2nd one is at the right time.

Having those 2 log messages right after one another is also kind of noisy, plus confusing. To reduce the confusion there would probably have to be some sort of INFO message in between saying the op is being rolled back, which helps explain the 2nd report.

There would be other issue too with logging twice. For example what if a service is failed and rollback-on-runtime-failure=false is used so there's no rollback? We don't want log the same failed service twice for one op.

I'll have to think whether I want that 16:54:18,810 logging even when the op rolls back. The basic point of the report is to report unusual MSC state at the end of an op, so really it's pointless to log it if the end state of the op has no unusual MSC state. The log already has ERROR messages for the missing / failed services that were detected while the op executed.

> There stuck some required service after unsuccessful command for adding CredentialStore with wrong filled relative-to attribute.
> --------------------------------------------------------------------------------------------------------------------------------
>
>                 Key: WFCORE-2351
>                 URL: https://issues.jboss.org/browse/WFCORE-2351
>             Project: WildFly Core
>          Issue Type: Bug
>          Components: Domain Management
>            Reporter: Hynek Švábek
>            Assignee: Brian Stansberry
>
> There stuck some required service after unsuccessful command for adding CredentialStore with wrong filled relative-to attribute.
> *Command with wrong filled relative-to attribute* 
> {code}
> /subsystem=elytron/credential-store=CredStore108:add(uri="cr-store://test/cs108.jceks?create.storage=true",  credential-reference={clear-text=pass123}, relative-to=non.exist.path.resource)
> {code}
> *You can see this log.*
> Especially information about New missing/unsatisfied dependencies:is important and it wouldn't be there.
> {code}
> 16:54:18,809 ERROR [org.jboss.as.controller.management-operation] (management-handler-thread - 8) WFLYCTL0013: Operation ("add") failed - address: ([
>     ("subsystem" => "elytron"),
>     ("credential-store" => "CredStore108")
> ]) - failure description: {
>     "WFLYCTL0412: Required services that are not installed:" => ["jboss.server.path.\"non.exist.path.resource\""],
>     "WFLYCTL0180: Services with missing/unavailable dependencies" => ["org.wildfly.security.credential-store.CredStore108 is missing [jboss.server.path.\"non.exist.path.resource\"]"]
> }
> 16:54:18,810 INFO  [org.jboss.as.controller] (management-handler-thread - 8) WFLYCTL0183: Service status report
> WFLYCTL0184:    New missing/unsatisfied dependencies:
>       service jboss.server.path."non.exist.path.resource" (missing) dependents: [service org.wildfly.security.credential-store.CredStore108] 
> {code}
> *Now we try process same command without relative-to attribute*
> {code}
> /subsystem=elytron/credential-store=CredStore108:add(uri="cr-store://test/cs108.jceks?create.storage=true",  credential-reference={clear-text=pass123})   
> {code}
> *Result is success but we can notice this in log:*
> {code}
> 16:55:33,093 INFO  [org.jboss.as.controller] (management-handler-thread - 10) WFLYCTL0183: Service status report
> WFLYCTL0185:    Newly corrected services:
>       service jboss.server.path."non.exist.path.resource" (no longer required)
> {code}



--
This message was sent by Atlassian JIRA
(v7.2.3#72005)