[JBoss JIRA] (WFCORE-1744) WFLYCC0034: Closing leaked controller client
by Brian Stansberry (JIRA)
[ https://issues.jboss.org/browse/WFCORE-1744?page=com.atlassian.jira.plugi... ]
Brian Stansberry commented on WFCORE-1744:
------------------------------------------
The CLI tool is not involved here, so I'm removing the CLI component, which is meant for issues in the CLI tool.
> WFLYCC0034: Closing leaked controller client
> --------------------------------------------
>
> Key: WFCORE-1744
> URL: https://issues.jboss.org/browse/WFCORE-1744
> Project: WildFly Core
> Issue Type: Bug
> Affects Versions: 3.0.0.Alpha5
> Reporter: Martin Choma
> Assignee: Jason Greene
>
> We are intermittently getting "WFLYCC0034: Closing leaked controller client" from RemotingModelControllerClient#finalize method.
> I wonder, isn't implementation of RemotingModelControllerClient#finalize() method [1] example of dangerous "safety net" implementation discussed in presentation "JVM finalize pitfalls" [2] ?
> [1] https://github.com/wildfly/wildfly-core/blob/master/controller-client/src...
> [2] https://www.youtube.com/watch?v=UrGP6pfb0H8
> [3]
> {noformat}
> 05:54:10 Aug 16, 2016 5:54:10 AM org.jboss.as.controller.client.impl.RemotingModelControllerClient finalize
> 05:54:10 WARN: WFLYCC0034: Closing leaked controller client
> 05:54:10 WFLYCC0030: Allocation stack trace:
> 05:54:10 at java.lang.Thread.getStackTrace(Thread.java:1552)
> 05:54:10 at org.jboss.as.controller.client.impl.RemotingModelControllerClient.<init>(RemotingModelControllerClient.java:74)
> 05:54:10 at org.jboss.as.controller.client.ModelControllerClient$Factory.create(ModelControllerClient.java:567)
> 05:54:10 at org.wildfly.plugin.common.ManagementClient.<init>(ManagementClient.java:37)
> 05:54:10 at org.wildfly.plugin.common.AbstractServerConnection.createClient(AbstractServerConnection.java:126)
> 05:54:10 at org.wildfly.plugin.server.StartMojo.execute(StartMojo.java:269)
> 05:54:10 at org.apache.maven.plugin.DefaultBuildPluginManager.executeMojo(DefaultBuildPluginManager.java:132)
> 05:54:10 at org.apache.maven.lifecycle.internal.MojoExecutor.execute(MojoExecutor.java:208)
> 05:54:10 at org.apache.maven.lifecycle.internal.MojoExecutor.execute(MojoExecutor.java:153)
> 05:54:10 at org.apache.maven.lifecycle.internal.MojoExecutor.execute(MojoExecutor.java:145)
> 05:54:10 at org.apache.maven.lifecycle.internal.LifecycleModuleBuilder.buildProject(LifecycleModuleBuilder.java:116)
> 05:54:10 at org.apache.maven.lifecycle.internal.LifecycleModuleBuilder.buildProject(LifecycleModuleBuilder.java:80)
> 05:54:10 at org.apache.maven.lifecycle.internal.builder.singlethreaded.SingleThreadedBuilder.build(SingleThreadedBuilder.java:51)
> 05:54:10 at org.apache.maven.lifecycle.internal.LifecycleStarter.execute(LifecycleStarter.java:120)
> 05:54:10 at org.apache.maven.DefaultMaven.doExecute(DefaultMaven.java:355)
> 05:54:10 at org.apache.maven.DefaultMaven.execute(DefaultMaven.java:155)
> 05:54:10 at org.apache.maven.cli.MavenCli.execute(MavenCli.java:584)
> 05:54:10 at org.apache.maven.cli.MavenCli.doMain(MavenCli.java:216)
> 05:54:10 at org.apache.maven.cli.MavenCli.main(MavenCli.java:160)
> 05:54:10 at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
> 05:54:10 at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
> 05:54:10 at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
> 05:54:10 at java.lang.reflect.Method.invoke(Method.java:498)
> 05:54:10 at org.codehaus.plexus.classworlds.launcher.Launcher.launchEnhanced(Launcher.java:289)
> 05:54:10 at org.codehaus.plexus.classworlds.launcher.Launcher.launch(Launcher.java:229)
> 05:54:10 at org.codehaus.plexus.classworlds.launcher.Launcher.mainWithExitCode(Launcher.java:415)
> 05:54:10 at org.codehaus.plexus.classworlds.launcher.Launcher.main(Launcher.java:356)
> {noformat}
--
This message was sent by Atlassian JIRA
(v6.4.11#64026)
9 years, 8 months
- 1
- 0
[JBoss JIRA] (WFCORE-1744) WFLYCC0034: Closing leaked controller client
by Brian Stansberry (JIRA)
[ https://issues.jboss.org/browse/WFCORE-1744?page=com.atlassian.jira.plugi... ]
Brian Stansberry reassigned WFCORE-1744:
----------------------------------------
Assignee: James Perkins (was: Jason Greene)
> WFLYCC0034: Closing leaked controller client
> --------------------------------------------
>
> Key: WFCORE-1744
> URL: https://issues.jboss.org/browse/WFCORE-1744
> Project: WildFly Core
> Issue Type: Bug
> Affects Versions: 3.0.0.Alpha5
> Reporter: Martin Choma
> Assignee: James Perkins
>
> We are intermittently getting "WFLYCC0034: Closing leaked controller client" from RemotingModelControllerClient#finalize method.
> I wonder, isn't implementation of RemotingModelControllerClient#finalize() method [1] example of dangerous "safety net" implementation discussed in presentation "JVM finalize pitfalls" [2] ?
> [1] https://github.com/wildfly/wildfly-core/blob/master/controller-client/src...
> [2] https://www.youtube.com/watch?v=UrGP6pfb0H8
> [3]
> {noformat}
> 05:54:10 Aug 16, 2016 5:54:10 AM org.jboss.as.controller.client.impl.RemotingModelControllerClient finalize
> 05:54:10 WARN: WFLYCC0034: Closing leaked controller client
> 05:54:10 WFLYCC0030: Allocation stack trace:
> 05:54:10 at java.lang.Thread.getStackTrace(Thread.java:1552)
> 05:54:10 at org.jboss.as.controller.client.impl.RemotingModelControllerClient.<init>(RemotingModelControllerClient.java:74)
> 05:54:10 at org.jboss.as.controller.client.ModelControllerClient$Factory.create(ModelControllerClient.java:567)
> 05:54:10 at org.wildfly.plugin.common.ManagementClient.<init>(ManagementClient.java:37)
> 05:54:10 at org.wildfly.plugin.common.AbstractServerConnection.createClient(AbstractServerConnection.java:126)
> 05:54:10 at org.wildfly.plugin.server.StartMojo.execute(StartMojo.java:269)
> 05:54:10 at org.apache.maven.plugin.DefaultBuildPluginManager.executeMojo(DefaultBuildPluginManager.java:132)
> 05:54:10 at org.apache.maven.lifecycle.internal.MojoExecutor.execute(MojoExecutor.java:208)
> 05:54:10 at org.apache.maven.lifecycle.internal.MojoExecutor.execute(MojoExecutor.java:153)
> 05:54:10 at org.apache.maven.lifecycle.internal.MojoExecutor.execute(MojoExecutor.java:145)
> 05:54:10 at org.apache.maven.lifecycle.internal.LifecycleModuleBuilder.buildProject(LifecycleModuleBuilder.java:116)
> 05:54:10 at org.apache.maven.lifecycle.internal.LifecycleModuleBuilder.buildProject(LifecycleModuleBuilder.java:80)
> 05:54:10 at org.apache.maven.lifecycle.internal.builder.singlethreaded.SingleThreadedBuilder.build(SingleThreadedBuilder.java:51)
> 05:54:10 at org.apache.maven.lifecycle.internal.LifecycleStarter.execute(LifecycleStarter.java:120)
> 05:54:10 at org.apache.maven.DefaultMaven.doExecute(DefaultMaven.java:355)
> 05:54:10 at org.apache.maven.DefaultMaven.execute(DefaultMaven.java:155)
> 05:54:10 at org.apache.maven.cli.MavenCli.execute(MavenCli.java:584)
> 05:54:10 at org.apache.maven.cli.MavenCli.doMain(MavenCli.java:216)
> 05:54:10 at org.apache.maven.cli.MavenCli.main(MavenCli.java:160)
> 05:54:10 at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
> 05:54:10 at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
> 05:54:10 at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
> 05:54:10 at java.lang.reflect.Method.invoke(Method.java:498)
> 05:54:10 at org.codehaus.plexus.classworlds.launcher.Launcher.launchEnhanced(Launcher.java:289)
> 05:54:10 at org.codehaus.plexus.classworlds.launcher.Launcher.launch(Launcher.java:229)
> 05:54:10 at org.codehaus.plexus.classworlds.launcher.Launcher.mainWithExitCode(Launcher.java:415)
> 05:54:10 at org.codehaus.plexus.classworlds.launcher.Launcher.main(Launcher.java:356)
> {noformat}
--
This message was sent by Atlassian JIRA
(v6.4.11#64026)
9 years, 8 months
- 1
- 0
[JBoss JIRA] (WFCORE-1744) WFLYCC0034: Closing leaked controller client
by Brian Stansberry (JIRA)
[ https://issues.jboss.org/browse/WFCORE-1744?page=com.atlassian.jira.plugi... ]
Brian Stansberry commented on WFCORE-1744:
------------------------------------------
Please provide full details on how/where you are seeing this. The issue description shows where the client was created, but the flaw is the code that isn't closing it. That looks to be the wildfly-maven plugin, but there is no 3.0.0.Alpha5 version of the wildfly-maven plugin.
> WFLYCC0034: Closing leaked controller client
> --------------------------------------------
>
> Key: WFCORE-1744
> URL: https://issues.jboss.org/browse/WFCORE-1744
> Project: WildFly Core
> Issue Type: Bug
> Components: CLI
> Affects Versions: 3.0.0.Alpha5
> Reporter: Martin Choma
> Assignee: Jason Greene
>
> We are intermittently getting "WFLYCC0034: Closing leaked controller client" from RemotingModelControllerClient#finalize method.
> I wonder, isn't implementation of RemotingModelControllerClient#finalize() method [1] example of dangerous "safety net" implementation discussed in presentation "JVM finalize pitfalls" [2] ?
> [1] https://github.com/wildfly/wildfly-core/blob/master/controller-client/src...
> [2] https://www.youtube.com/watch?v=UrGP6pfb0H8
> [3]
> {noformat}
> 05:54:10 Aug 16, 2016 5:54:10 AM org.jboss.as.controller.client.impl.RemotingModelControllerClient finalize
> 05:54:10 WARN: WFLYCC0034: Closing leaked controller client
> 05:54:10 WFLYCC0030: Allocation stack trace:
> 05:54:10 at java.lang.Thread.getStackTrace(Thread.java:1552)
> 05:54:10 at org.jboss.as.controller.client.impl.RemotingModelControllerClient.<init>(RemotingModelControllerClient.java:74)
> 05:54:10 at org.jboss.as.controller.client.ModelControllerClient$Factory.create(ModelControllerClient.java:567)
> 05:54:10 at org.wildfly.plugin.common.ManagementClient.<init>(ManagementClient.java:37)
> 05:54:10 at org.wildfly.plugin.common.AbstractServerConnection.createClient(AbstractServerConnection.java:126)
> 05:54:10 at org.wildfly.plugin.server.StartMojo.execute(StartMojo.java:269)
> 05:54:10 at org.apache.maven.plugin.DefaultBuildPluginManager.executeMojo(DefaultBuildPluginManager.java:132)
> 05:54:10 at org.apache.maven.lifecycle.internal.MojoExecutor.execute(MojoExecutor.java:208)
> 05:54:10 at org.apache.maven.lifecycle.internal.MojoExecutor.execute(MojoExecutor.java:153)
> 05:54:10 at org.apache.maven.lifecycle.internal.MojoExecutor.execute(MojoExecutor.java:145)
> 05:54:10 at org.apache.maven.lifecycle.internal.LifecycleModuleBuilder.buildProject(LifecycleModuleBuilder.java:116)
> 05:54:10 at org.apache.maven.lifecycle.internal.LifecycleModuleBuilder.buildProject(LifecycleModuleBuilder.java:80)
> 05:54:10 at org.apache.maven.lifecycle.internal.builder.singlethreaded.SingleThreadedBuilder.build(SingleThreadedBuilder.java:51)
> 05:54:10 at org.apache.maven.lifecycle.internal.LifecycleStarter.execute(LifecycleStarter.java:120)
> 05:54:10 at org.apache.maven.DefaultMaven.doExecute(DefaultMaven.java:355)
> 05:54:10 at org.apache.maven.DefaultMaven.execute(DefaultMaven.java:155)
> 05:54:10 at org.apache.maven.cli.MavenCli.execute(MavenCli.java:584)
> 05:54:10 at org.apache.maven.cli.MavenCli.doMain(MavenCli.java:216)
> 05:54:10 at org.apache.maven.cli.MavenCli.main(MavenCli.java:160)
> 05:54:10 at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
> 05:54:10 at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
> 05:54:10 at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
> 05:54:10 at java.lang.reflect.Method.invoke(Method.java:498)
> 05:54:10 at org.codehaus.plexus.classworlds.launcher.Launcher.launchEnhanced(Launcher.java:289)
> 05:54:10 at org.codehaus.plexus.classworlds.launcher.Launcher.launch(Launcher.java:229)
> 05:54:10 at org.codehaus.plexus.classworlds.launcher.Launcher.mainWithExitCode(Launcher.java:415)
> 05:54:10 at org.codehaus.plexus.classworlds.launcher.Launcher.main(Launcher.java:356)
> {noformat}
--
This message was sent by Atlassian JIRA
(v6.4.11#64026)
9 years, 8 months
- 1
- 0
[JBoss JIRA] (WFCORE-1745) CLI support for response attachments
by Brian Stansberry (JIRA)
Brian Stansberry created WFCORE-1745:
----------------------------------------
Summary: CLI support for response attachments
Key: WFCORE-1745
URL: https://issues.jboss.org/browse/WFCORE-1745
Project: WildFly Core
Issue Type: Feature Request
Components: CLI
Reporter: Jean-Francois Denise
Assignee: Jean-Francois Denise
CLI doesn't support the streams attached to a response. Incremental deployment support offers today the ability to read the content of a deployment. It would be interesting to operate it from the CLI. Some resource (such as the log file) expose some attributes as stream.
The following operations are returning streams:
/subsystem=logging/log-file=server.log:read-attribute(name=stream)
/subsystem=logging/log-file=server.log:read-resource(include-runtime)
/deployment=toto:read-content(path=index.html)
As we can see, streams can be located in attributes, as operation response, inside a resource.
The CLI offers 2 way to approach the problem:
1) Extend the Low level operation support with a way to save/display attached streams. This would require some XML configuration and possibly UI workflow to prompt user for the right action. Making from stream to file path would be not ideal and far from being user friendly. The good side is tha tit would work in any case (batch, non batch). The XML configuration can be a bit complex and prompting user is not an ideal workflow.
2) Define a new high level command that would cope with any operation.
Such command would look like:
attachment save --operation=/subsystem=logging/log-file=server.log:read-attribute(name=stream) --file=/my/local/path/to/file
attachment display --operation=/subsystem=logging/log-file=server.log:read-attribute(name=stream)
- No risk to impact existing scripts. This is a new feature, so people would have to update their scripts to add the command.
- The challenge is located in mapping a Stream to a file name. The user provides the name he wants. Furthermore, in interactive mode, the user can use completion to complete this target file.
- No more prompting, the user knows ahead of time what he wants to do.
- Problem is that batch mode doesn't re-dispatch each step response to each input command. So some logic should be needed to properly handle streams in batch.
--
This message was sent by Atlassian JIRA
(v6.4.11#64026)
9 years, 8 months
- 1
- 0
[JBoss JIRA] (DROOLS-1262) Logging level DEBUG should be less verbose: "Fire Loop" & "State was" should be trace
by Geoffrey De Smet (JIRA)
[ https://issues.jboss.org/browse/DROOLS-1262?page=com.atlassian.jira.plugi... ]
Geoffrey De Smet updated DROOLS-1262:
-------------------------------------
Description:
In the latest 6.4 product patches, I am seeing customers that are up to *10 times slower* due to drools in their optaplanner cases. It turns out that they have no logging configuration and many systems - such as WildFly use DEBUG logging by default (often to a file so no one notices it).
Meanwhile the log fills up with this:
{code}
2016-08-29 15:20:57,338 [SwingWorker-pool-2-thread-1] drools DEBUG State was INACTIVE is now FIRING_ALL_RULES
2016-08-29 15:20:57,338 [SwingWorker-pool-2-thread-1] drools DEBUG Fire Loop
2016-08-29 15:20:57,338 [SwingWorker-pool-2-thread-1] drools DEBUG Fire Loop
2016-08-29 15:20:57,338 [SwingWorker-pool-2-thread-1] drools DEBUG Fire Loop
2016-08-29 15:20:57,338 [SwingWorker-pool-2-thread-1] drools DEBUG Fire Loop
2016-08-29 15:20:57,338 [SwingWorker-pool-2-thread-1] drools DEBUG Fire Loop
2016-08-29 15:20:57,338 [SwingWorker-pool-2-thread-1] drools DEBUG State was FIRING_ALL_RULES is now HALTING
2016-08-29 15:20:57,338 [SwingWorker-pool-2-thread-1] drools DEBUG State was HALTING is now INACTIVE
2016-08-29 15:20:57,338 [SwingWorker-pool-2-thread-1] optaplanner TRACE Move index (100), score (-10hard/-128070soft), accepted (false), move (CloudProcess-67 {CloudComputer-45} <-> CloudProcess-147 {CloudComputer-18}).
2016-08-29 15:20:57,338 [SwingWorker-pool-2-thread-1] drools DEBUG State was INACTIVE is now FIRING_ALL_RULES
2016-08-29 15:20:57,338 [SwingWorker-pool-2-thread-1] drools DEBUG Fire Loop
2016-08-29 15:20:57,338 [SwingWorker-pool-2-thread-1] drools DEBUG Fire Loop
2016-08-29 15:20:57,338 [SwingWorker-pool-2-thread-1] drools DEBUG Fire Loop
2016-08-29 15:20:57,338 [SwingWorker-pool-2-thread-1] drools DEBUG Fire Loop
2016-08-29 15:20:57,338 [SwingWorker-pool-2-thread-1] drools DEBUG Fire Loop
2016-08-29 15:20:57,338 [SwingWorker-pool-2-thread-1] drools DEBUG State was FIRING_ALL_RULES is now HALTING
2016-08-29 15:20:57,338 [SwingWorker-pool-2-thread-1] drools DEBUG State was HALTING is now INACTIVE
2016-08-29 15:20:57,338 [SwingWorker-pool-2-thread-1] optaplanner TRACE Move index (101), score (0hard/-128070soft), accepted (true), move (CloudProcess-104 {CloudComputer-89} <-> CloudProcess-295 {CloudComputer-26}).
2016-08-29 15:20:57,338 [SwingWorker-pool-2-thread-1] optaplanner DEBUG LS step (6730), time spent (3432), score (0hard/-128070soft), best score (0hard/-126690soft), accepted/selected move count (1/102), picked move (CloudProcess-104 {CloudComputer-89} <-> CloudProcess-295 {CloudComputer-26}).
{code}
but without the optaplanner TRACE lines (they are just here to show that drools debug is 7 times as verbose as optaplanner trace here).
Solution proposal A): remove the line "Fire Loop" and put "State was" on trace logging.
Solution proposal B): collapse the 5 lines "Fire Loop" into "5 fire loops" and put "State was" on trace logging.
Solution proposal C): put the line "Fire Loop" and "State was" on trace logging.
I personally dislike this one - even trace logging should still be useful and not more verbose that it needs to be (although it should log in high detail).
This should be fixed for 7.0, 6.5.x and I 'll ask QA to consider adding it for 6.4.x.
was:
In the latest 6.4 product patches, I am seeing customers that are up to *10 times slower* due to drools in their optaplanner cases. It turns out that they have no logging configuration and many systems - such as WildFly use DEBUG logging by default (often to a file so no one notices it).
Meanwhile the log fills up with this:
{code}
2016-08-29 15:20:57,338 [SwingWorker-pool-2-thread-1] drools DEBUG State was INACTIVE is now FIRING_ALL_RULES
2016-08-29 15:20:57,338 [SwingWorker-pool-2-thread-1] drools DEBUG Fire Loop
2016-08-29 15:20:57,338 [SwingWorker-pool-2-thread-1] drools DEBUG Fire Loop
2016-08-29 15:20:57,338 [SwingWorker-pool-2-thread-1] drools DEBUG Fire Loop
2016-08-29 15:20:57,338 [SwingWorker-pool-2-thread-1] drools DEBUG Fire Loop
2016-08-29 15:20:57,338 [SwingWorker-pool-2-thread-1] drools DEBUG Fire Loop
2016-08-29 15:20:57,338 [SwingWorker-pool-2-thread-1] drools DEBUG State was FIRING_ALL_RULES is now HALTING
2016-08-29 15:20:57,338 [SwingWorker-pool-2-thread-1] drools DEBUG State was HALTING is now INACTIVE
2016-08-29 15:20:57,338 [SwingWorker-pool-2-thread-1] optaplanner TRACE Move index (0), score (-10hard/-128070soft), accepted (false), move (CloudProcess-67 {CloudComputer-45} <-> CloudProcess-147 {CloudComputer-18}).
2016-08-29 15:20:57,338 [SwingWorker-pool-2-thread-1] drools DEBUG State was INACTIVE is now FIRING_ALL_RULES
2016-08-29 15:20:57,338 [SwingWorker-pool-2-thread-1] drools DEBUG Fire Loop
2016-08-29 15:20:57,338 [SwingWorker-pool-2-thread-1] drools DEBUG Fire Loop
2016-08-29 15:20:57,338 [SwingWorker-pool-2-thread-1] drools DEBUG Fire Loop
2016-08-29 15:20:57,338 [SwingWorker-pool-2-thread-1] drools DEBUG Fire Loop
2016-08-29 15:20:57,338 [SwingWorker-pool-2-thread-1] drools DEBUG Fire Loop
2016-08-29 15:20:57,338 [SwingWorker-pool-2-thread-1] drools DEBUG State was FIRING_ALL_RULES is now HALTING
2016-08-29 15:20:57,338 [SwingWorker-pool-2-thread-1] drools DEBUG State was HALTING is now INACTIVE
2016-08-29 15:20:57,338 [SwingWorker-pool-2-thread-1] optaplanner TRACE Move index (1), score (0hard/-128070soft), accepted (true), move (CloudProcess-104 {CloudComputer-89} <-> CloudProcess-295 {CloudComputer-26}).
2016-08-29 15:20:57,338 [SwingWorker-pool-2-thread-1] optaplanner DEBUG LS step (6730), time spent (3432), score (0hard/-128070soft), best score (0hard/-126690soft), accepted/selected move count (1/2), picked move (CloudProcess-104 {CloudComputer-89} <-> CloudProcess-295 {CloudComputer-26}).
{code}
but without the optaplanner TRACE lines (they are just here to show that drools debug is 7 times as verbose as optaplanner trace here).
Solution proposal A): remove the line "Fire Loop" and put "State was" on trace logging.
Solution proposal B): collapse the 5 lines "Fire Loop" into "5 fire loops" and put "State was" on trace logging.
Solution proposal C): put the line "Fire Loop" and "State was" on trace logging.
I personally dislike this one - even trace logging should still be useful and not more verbose that it needs to be (although it should log in high detail).
This should be fixed for 7.0, 6.5.x and I 'll ask QA to consider adding it for 6.4.x.
> Logging level DEBUG should be less verbose: "Fire Loop" & "State was" should be trace
> -------------------------------------------------------------------------------------
>
> Key: DROOLS-1262
> URL: https://issues.jboss.org/browse/DROOLS-1262
> Project: Drools
> Issue Type: Bug
> Components: core engine
> Affects Versions: 6.4.0.Final, 6.5.0.CR1, 7.0.0.Beta1
> Reporter: Geoffrey De Smet
> Assignee: Mario Fusco
> Priority: Critical
>
> In the latest 6.4 product patches, I am seeing customers that are up to *10 times slower* due to drools in their optaplanner cases. It turns out that they have no logging configuration and many systems - such as WildFly use DEBUG logging by default (often to a file so no one notices it).
> Meanwhile the log fills up with this:
> {code}
> 2016-08-29 15:20:57,338 [SwingWorker-pool-2-thread-1] drools DEBUG State was INACTIVE is now FIRING_ALL_RULES
> 2016-08-29 15:20:57,338 [SwingWorker-pool-2-thread-1] drools DEBUG Fire Loop
> 2016-08-29 15:20:57,338 [SwingWorker-pool-2-thread-1] drools DEBUG Fire Loop
> 2016-08-29 15:20:57,338 [SwingWorker-pool-2-thread-1] drools DEBUG Fire Loop
> 2016-08-29 15:20:57,338 [SwingWorker-pool-2-thread-1] drools DEBUG Fire Loop
> 2016-08-29 15:20:57,338 [SwingWorker-pool-2-thread-1] drools DEBUG Fire Loop
> 2016-08-29 15:20:57,338 [SwingWorker-pool-2-thread-1] drools DEBUG State was FIRING_ALL_RULES is now HALTING
> 2016-08-29 15:20:57,338 [SwingWorker-pool-2-thread-1] drools DEBUG State was HALTING is now INACTIVE
> 2016-08-29 15:20:57,338 [SwingWorker-pool-2-thread-1] optaplanner TRACE Move index (100), score (-10hard/-128070soft), accepted (false), move (CloudProcess-67 {CloudComputer-45} <-> CloudProcess-147 {CloudComputer-18}).
> 2016-08-29 15:20:57,338 [SwingWorker-pool-2-thread-1] drools DEBUG State was INACTIVE is now FIRING_ALL_RULES
> 2016-08-29 15:20:57,338 [SwingWorker-pool-2-thread-1] drools DEBUG Fire Loop
> 2016-08-29 15:20:57,338 [SwingWorker-pool-2-thread-1] drools DEBUG Fire Loop
> 2016-08-29 15:20:57,338 [SwingWorker-pool-2-thread-1] drools DEBUG Fire Loop
> 2016-08-29 15:20:57,338 [SwingWorker-pool-2-thread-1] drools DEBUG Fire Loop
> 2016-08-29 15:20:57,338 [SwingWorker-pool-2-thread-1] drools DEBUG Fire Loop
> 2016-08-29 15:20:57,338 [SwingWorker-pool-2-thread-1] drools DEBUG State was FIRING_ALL_RULES is now HALTING
> 2016-08-29 15:20:57,338 [SwingWorker-pool-2-thread-1] drools DEBUG State was HALTING is now INACTIVE
> 2016-08-29 15:20:57,338 [SwingWorker-pool-2-thread-1] optaplanner TRACE Move index (101), score (0hard/-128070soft), accepted (true), move (CloudProcess-104 {CloudComputer-89} <-> CloudProcess-295 {CloudComputer-26}).
> 2016-08-29 15:20:57,338 [SwingWorker-pool-2-thread-1] optaplanner DEBUG LS step (6730), time spent (3432), score (0hard/-128070soft), best score (0hard/-126690soft), accepted/selected move count (1/102), picked move (CloudProcess-104 {CloudComputer-89} <-> CloudProcess-295 {CloudComputer-26}).
> {code}
> but without the optaplanner TRACE lines (they are just here to show that drools debug is 7 times as verbose as optaplanner trace here).
> Solution proposal A): remove the line "Fire Loop" and put "State was" on trace logging.
> Solution proposal B): collapse the 5 lines "Fire Loop" into "5 fire loops" and put "State was" on trace logging.
> Solution proposal C): put the line "Fire Loop" and "State was" on trace logging.
> I personally dislike this one - even trace logging should still be useful and not more verbose that it needs to be (although it should log in high detail).
> This should be fixed for 7.0, 6.5.x and I 'll ask QA to consider adding it for 6.4.x.
--
This message was sent by Atlassian JIRA
(v6.4.11#64026)
9 years, 8 months
- 1
- 0
[JBoss JIRA] (DROOLS-1262) Logging level DEBUG should be less verbose: "Fire Loop" & "State was" should be trace
by Geoffrey De Smet (JIRA)
[ https://issues.jboss.org/browse/DROOLS-1262?page=com.atlassian.jira.plugi... ]
Geoffrey De Smet updated DROOLS-1262:
-------------------------------------
Description:
In the latest 6.4 product patches, I am seeing customers that are up to *10 times slower* due to drools in their optaplanner cases. It turns out that they have no logging configuration and many systems - such as WildFly use DEBUG logging by default (often to a file so no one notices it).
Meanwhile the log fills up with this:
{code}
2016-08-29 15:20:57,338 [SwingWorker-pool-2-thread-1] drools DEBUG State was INACTIVE is now FIRING_ALL_RULES
2016-08-29 15:20:57,338 [SwingWorker-pool-2-thread-1] drools DEBUG Fire Loop
2016-08-29 15:20:57,338 [SwingWorker-pool-2-thread-1] drools DEBUG Fire Loop
2016-08-29 15:20:57,338 [SwingWorker-pool-2-thread-1] drools DEBUG Fire Loop
2016-08-29 15:20:57,338 [SwingWorker-pool-2-thread-1] drools DEBUG Fire Loop
2016-08-29 15:20:57,338 [SwingWorker-pool-2-thread-1] drools DEBUG Fire Loop
2016-08-29 15:20:57,338 [SwingWorker-pool-2-thread-1] drools DEBUG State was FIRING_ALL_RULES is now HALTING
2016-08-29 15:20:57,338 [SwingWorker-pool-2-thread-1] drools DEBUG State was HALTING is now INACTIVE
2016-08-29 15:20:57,338 [SwingWorker-pool-2-thread-1] optaplanner TRACE Move index (0), score (-10hard/-128070soft), accepted (false), move (CloudProcess-67 {CloudComputer-45} <-> CloudProcess-147 {CloudComputer-18}).
2016-08-29 15:20:57,338 [SwingWorker-pool-2-thread-1] drools DEBUG State was INACTIVE is now FIRING_ALL_RULES
2016-08-29 15:20:57,338 [SwingWorker-pool-2-thread-1] drools DEBUG Fire Loop
2016-08-29 15:20:57,338 [SwingWorker-pool-2-thread-1] drools DEBUG Fire Loop
2016-08-29 15:20:57,338 [SwingWorker-pool-2-thread-1] drools DEBUG Fire Loop
2016-08-29 15:20:57,338 [SwingWorker-pool-2-thread-1] drools DEBUG Fire Loop
2016-08-29 15:20:57,338 [SwingWorker-pool-2-thread-1] drools DEBUG Fire Loop
2016-08-29 15:20:57,338 [SwingWorker-pool-2-thread-1] drools DEBUG State was FIRING_ALL_RULES is now HALTING
2016-08-29 15:20:57,338 [SwingWorker-pool-2-thread-1] drools DEBUG State was HALTING is now INACTIVE
2016-08-29 15:20:57,338 [SwingWorker-pool-2-thread-1] optaplanner TRACE Move index (1), score (0hard/-128070soft), accepted (true), move (CloudProcess-104 {CloudComputer-89} <-> CloudProcess-295 {CloudComputer-26}).
2016-08-29 15:20:57,338 [SwingWorker-pool-2-thread-1] optaplanner DEBUG LS step (6730), time spent (3432), score (0hard/-128070soft), best score (0hard/-126690soft), accepted/selected move count (1/2), picked move (CloudProcess-104 {CloudComputer-89} <-> CloudProcess-295 {CloudComputer-26}).
{code}
but without the optaplanner TRACE lines (they are just here to show that drools debug is 7 times as verbose as optaplanner trace here).
Solution proposal A): remove the line "Fire Loop" and put "State was" on trace logging.
Solution proposal B): collapse the 5 lines "Fire Loop" into "5 fire loops" and put "State was" on trace logging.
Solution proposal C): put the line "Fire Loop" and "State was" on trace logging.
I personally dislike this one - even trace logging should still be useful and not more verbose that it needs to be (although it should log in high detail).
This should be fixed for 7.0, 6.5.x and I 'll ask QA to consider adding it for 6.4.x.
was:
In the latest 6.4 product patches, I am seeing customers that are up to *10 times slower* due to drools in their optaplanner cases. It turns out that they have no logging configuration and many systems - such as WildFly use DEBUG logging by default (often to a file so no one notices it).
Meanwhile the log fills up with this:
{code}
2016-08-29 15:20:57,338 [SwingWorker-pool-2-thread-1] DEBUG State was INACTIVE is now FIRING_ALL_RULES
2016-08-29 15:20:57,338 [SwingWorker-pool-2-thread-1] DEBUG Fire Loop
2016-08-29 15:20:57,338 [SwingWorker-pool-2-thread-1] DEBUG Fire Loop
2016-08-29 15:20:57,338 [SwingWorker-pool-2-thread-1] DEBUG Fire Loop
2016-08-29 15:20:57,338 [SwingWorker-pool-2-thread-1] DEBUG Fire Loop
2016-08-29 15:20:57,338 [SwingWorker-pool-2-thread-1] DEBUG Fire Loop
2016-08-29 15:20:57,338 [SwingWorker-pool-2-thread-1] DEBUG State was FIRING_ALL_RULES is now HALTING
2016-08-29 15:20:57,338 [SwingWorker-pool-2-thread-1] DEBUG State was HALTING is now INACTIVE
2016-08-29 15:20:57,338 [SwingWorker-pool-2-thread-1] TRACE Move index (0), score (-10hard/-128070soft), accepted (false), move (CloudProcess-67 {CloudComputer-45} <-> CloudProcess-147 {CloudComputer-18}).
2016-08-29 15:20:57,338 [SwingWorker-pool-2-thread-1] DEBUG State was INACTIVE is now FIRING_ALL_RULES
2016-08-29 15:20:57,338 [SwingWorker-pool-2-thread-1] DEBUG Fire Loop
2016-08-29 15:20:57,338 [SwingWorker-pool-2-thread-1] DEBUG Fire Loop
2016-08-29 15:20:57,338 [SwingWorker-pool-2-thread-1] DEBUG Fire Loop
2016-08-29 15:20:57,338 [SwingWorker-pool-2-thread-1] DEBUG Fire Loop
2016-08-29 15:20:57,338 [SwingWorker-pool-2-thread-1] DEBUG Fire Loop
2016-08-29 15:20:57,338 [SwingWorker-pool-2-thread-1] DEBUG State was FIRING_ALL_RULES is now HALTING
2016-08-29 15:20:57,338 [SwingWorker-pool-2-thread-1] DEBUG State was HALTING is now INACTIVE
2016-08-29 15:20:57,338 [SwingWorker-pool-2-thread-1] TRACE Move index (1), score (0hard/-128070soft), accepted (true), move (CloudProcess-104 {CloudComputer-89} <-> CloudProcess-295 {CloudComputer-26}).
2016-08-29 15:20:57,338 [SwingWorker-pool-2-thread-1] DEBUG LS step (6730), time spent (3432), score (0hard/-128070soft), best score (0hard/-126690soft), accepted/selected move count (1/2), picked move (CloudProcess-104 {CloudComputer-89} <-> CloudProcess-295 {CloudComputer-26}).
{code}
but without the optaplanner TRACE lines.
Solution proposal A): remove the line "Fire Loop" and put "State was" on trace logging.
Solution proposal B): collapse the 5 lines "Fire Loop" into "5 fire loops" and put "State was" on trace logging.
Solution proposal C): put the line "Fire Loop" and "State was" on trace logging.
I personally dislike this one - even trace logging should still be useful and not more verbose that it needs to be (although it should log in high detail).
This should be fixed for 7.0, 6.5.x and I 'll ask QA to consider adding it for 6.4.x.
> Logging level DEBUG should be less verbose: "Fire Loop" & "State was" should be trace
> -------------------------------------------------------------------------------------
>
> Key: DROOLS-1262
> URL: https://issues.jboss.org/browse/DROOLS-1262
> Project: Drools
> Issue Type: Bug
> Components: core engine
> Affects Versions: 6.4.0.Final, 6.5.0.CR1, 7.0.0.Beta1
> Reporter: Geoffrey De Smet
> Assignee: Mario Fusco
> Priority: Critical
>
> In the latest 6.4 product patches, I am seeing customers that are up to *10 times slower* due to drools in their optaplanner cases. It turns out that they have no logging configuration and many systems - such as WildFly use DEBUG logging by default (often to a file so no one notices it).
> Meanwhile the log fills up with this:
> {code}
> 2016-08-29 15:20:57,338 [SwingWorker-pool-2-thread-1] drools DEBUG State was INACTIVE is now FIRING_ALL_RULES
> 2016-08-29 15:20:57,338 [SwingWorker-pool-2-thread-1] drools DEBUG Fire Loop
> 2016-08-29 15:20:57,338 [SwingWorker-pool-2-thread-1] drools DEBUG Fire Loop
> 2016-08-29 15:20:57,338 [SwingWorker-pool-2-thread-1] drools DEBUG Fire Loop
> 2016-08-29 15:20:57,338 [SwingWorker-pool-2-thread-1] drools DEBUG Fire Loop
> 2016-08-29 15:20:57,338 [SwingWorker-pool-2-thread-1] drools DEBUG Fire Loop
> 2016-08-29 15:20:57,338 [SwingWorker-pool-2-thread-1] drools DEBUG State was FIRING_ALL_RULES is now HALTING
> 2016-08-29 15:20:57,338 [SwingWorker-pool-2-thread-1] drools DEBUG State was HALTING is now INACTIVE
> 2016-08-29 15:20:57,338 [SwingWorker-pool-2-thread-1] optaplanner TRACE Move index (0), score (-10hard/-128070soft), accepted (false), move (CloudProcess-67 {CloudComputer-45} <-> CloudProcess-147 {CloudComputer-18}).
> 2016-08-29 15:20:57,338 [SwingWorker-pool-2-thread-1] drools DEBUG State was INACTIVE is now FIRING_ALL_RULES
> 2016-08-29 15:20:57,338 [SwingWorker-pool-2-thread-1] drools DEBUG Fire Loop
> 2016-08-29 15:20:57,338 [SwingWorker-pool-2-thread-1] drools DEBUG Fire Loop
> 2016-08-29 15:20:57,338 [SwingWorker-pool-2-thread-1] drools DEBUG Fire Loop
> 2016-08-29 15:20:57,338 [SwingWorker-pool-2-thread-1] drools DEBUG Fire Loop
> 2016-08-29 15:20:57,338 [SwingWorker-pool-2-thread-1] drools DEBUG Fire Loop
> 2016-08-29 15:20:57,338 [SwingWorker-pool-2-thread-1] drools DEBUG State was FIRING_ALL_RULES is now HALTING
> 2016-08-29 15:20:57,338 [SwingWorker-pool-2-thread-1] drools DEBUG State was HALTING is now INACTIVE
> 2016-08-29 15:20:57,338 [SwingWorker-pool-2-thread-1] optaplanner TRACE Move index (1), score (0hard/-128070soft), accepted (true), move (CloudProcess-104 {CloudComputer-89} <-> CloudProcess-295 {CloudComputer-26}).
> 2016-08-29 15:20:57,338 [SwingWorker-pool-2-thread-1] optaplanner DEBUG LS step (6730), time spent (3432), score (0hard/-128070soft), best score (0hard/-126690soft), accepted/selected move count (1/2), picked move (CloudProcess-104 {CloudComputer-89} <-> CloudProcess-295 {CloudComputer-26}).
> {code}
> but without the optaplanner TRACE lines (they are just here to show that drools debug is 7 times as verbose as optaplanner trace here).
> Solution proposal A): remove the line "Fire Loop" and put "State was" on trace logging.
> Solution proposal B): collapse the 5 lines "Fire Loop" into "5 fire loops" and put "State was" on trace logging.
> Solution proposal C): put the line "Fire Loop" and "State was" on trace logging.
> I personally dislike this one - even trace logging should still be useful and not more verbose that it needs to be (although it should log in high detail).
> This should be fixed for 7.0, 6.5.x and I 'll ask QA to consider adding it for 6.4.x.
--
This message was sent by Atlassian JIRA
(v6.4.11#64026)
9 years, 8 months
- 1
- 0
[JBoss JIRA] (DROOLS-1262) Logging level DEBUG should be less verbose: "Fire Loop" & "State was" should be trace
by Geoffrey De Smet (JIRA)
[ https://issues.jboss.org/browse/DROOLS-1262?page=com.atlassian.jira.plugi... ]
Geoffrey De Smet updated DROOLS-1262:
-------------------------------------
Description:
In the latest 6.4 product patches, I am seeing customers that are up to *10 times slower* due to drools in their optaplanner cases. It turns out that they have no logging configuration and many systems - such as WildFly use DEBUG logging by default (often to a file so no one notices it).
Meanwhile the log fills up with this:
{code}
2016-08-29 15:20:57,338 [SwingWorker-pool-2-thread-1] DEBUG State was INACTIVE is now FIRING_ALL_RULES
2016-08-29 15:20:57,338 [SwingWorker-pool-2-thread-1] DEBUG Fire Loop
2016-08-29 15:20:57,338 [SwingWorker-pool-2-thread-1] DEBUG Fire Loop
2016-08-29 15:20:57,338 [SwingWorker-pool-2-thread-1] DEBUG Fire Loop
2016-08-29 15:20:57,338 [SwingWorker-pool-2-thread-1] DEBUG Fire Loop
2016-08-29 15:20:57,338 [SwingWorker-pool-2-thread-1] DEBUG Fire Loop
2016-08-29 15:20:57,338 [SwingWorker-pool-2-thread-1] DEBUG State was FIRING_ALL_RULES is now HALTING
2016-08-29 15:20:57,338 [SwingWorker-pool-2-thread-1] DEBUG State was HALTING is now INACTIVE
2016-08-29 15:20:57,338 [SwingWorker-pool-2-thread-1] TRACE Move index (0), score (-10hard/-128070soft), accepted (false), move (CloudProcess-67 {CloudComputer-45} <-> CloudProcess-147 {CloudComputer-18}).
2016-08-29 15:20:57,338 [SwingWorker-pool-2-thread-1] DEBUG State was INACTIVE is now FIRING_ALL_RULES
2016-08-29 15:20:57,338 [SwingWorker-pool-2-thread-1] DEBUG Fire Loop
2016-08-29 15:20:57,338 [SwingWorker-pool-2-thread-1] DEBUG Fire Loop
2016-08-29 15:20:57,338 [SwingWorker-pool-2-thread-1] DEBUG Fire Loop
2016-08-29 15:20:57,338 [SwingWorker-pool-2-thread-1] DEBUG Fire Loop
2016-08-29 15:20:57,338 [SwingWorker-pool-2-thread-1] DEBUG Fire Loop
2016-08-29 15:20:57,338 [SwingWorker-pool-2-thread-1] DEBUG State was FIRING_ALL_RULES is now HALTING
2016-08-29 15:20:57,338 [SwingWorker-pool-2-thread-1] DEBUG State was HALTING is now INACTIVE
2016-08-29 15:20:57,338 [SwingWorker-pool-2-thread-1] TRACE Move index (1), score (0hard/-128070soft), accepted (true), move (CloudProcess-104 {CloudComputer-89} <-> CloudProcess-295 {CloudComputer-26}).
2016-08-29 15:20:57,338 [SwingWorker-pool-2-thread-1] DEBUG LS step (6730), time spent (3432), score (0hard/-128070soft), best score (0hard/-126690soft), accepted/selected move count (1/2), picked move (CloudProcess-104 {CloudComputer-89} <-> CloudProcess-295 {CloudComputer-26}).
{code}
but without the optaplanner TRACE lines.
Solution proposal A): remove the line "Fire Loop" and put "State was" on trace logging.
Solution proposal B): collapse the 5 lines "Fire Loop" into "5 fire loops" and put "State was" on trace logging.
Solution proposal C): put the line "Fire Loop" and "State was" on trace logging.
I personally dislike this one - even trace logging should still be useful and not more verbose that it needs to be (although it should log in high detail).
This should be fixed for 7.0, 6.5.x and I 'll ask QA to consider adding it for 6.4.x.
was:
In the latest 6.4 product patches, I am seeing customers that are up to 10 times slower due to drools in their optaplanner cases. It turns out that they have no logging configuration and many systems - such as WildFly use DEBUG logging by default (often to a file so no one notices it).
Meanwhile the log fills up with this:
{code}
2016-08-29 15:20:57,338 [SwingWorker-pool-2-thread-1] DEBUG State was INACTIVE is now FIRING_ALL_RULES
2016-08-29 15:20:57,338 [SwingWorker-pool-2-thread-1] DEBUG Fire Loop
2016-08-29 15:20:57,338 [SwingWorker-pool-2-thread-1] DEBUG Fire Loop
2016-08-29 15:20:57,338 [SwingWorker-pool-2-thread-1] DEBUG Fire Loop
2016-08-29 15:20:57,338 [SwingWorker-pool-2-thread-1] DEBUG Fire Loop
2016-08-29 15:20:57,338 [SwingWorker-pool-2-thread-1] DEBUG Fire Loop
2016-08-29 15:20:57,338 [SwingWorker-pool-2-thread-1] DEBUG State was FIRING_ALL_RULES is now HALTING
2016-08-29 15:20:57,338 [SwingWorker-pool-2-thread-1] DEBUG State was HALTING is now INACTIVE
2016-08-29 15:20:57,338 [SwingWorker-pool-2-thread-1] TRACE Move index (0), score (-10hard/-128070soft), accepted (false), move (CloudProcess-67 {CloudComputer-45} <-> CloudProcess-147 {CloudComputer-18}).
2016-08-29 15:20:57,338 [SwingWorker-pool-2-thread-1] DEBUG State was INACTIVE is now FIRING_ALL_RULES
2016-08-29 15:20:57,338 [SwingWorker-pool-2-thread-1] DEBUG Fire Loop
2016-08-29 15:20:57,338 [SwingWorker-pool-2-thread-1] DEBUG Fire Loop
2016-08-29 15:20:57,338 [SwingWorker-pool-2-thread-1] DEBUG Fire Loop
2016-08-29 15:20:57,338 [SwingWorker-pool-2-thread-1] DEBUG Fire Loop
2016-08-29 15:20:57,338 [SwingWorker-pool-2-thread-1] DEBUG Fire Loop
2016-08-29 15:20:57,338 [SwingWorker-pool-2-thread-1] DEBUG State was FIRING_ALL_RULES is now HALTING
2016-08-29 15:20:57,338 [SwingWorker-pool-2-thread-1] DEBUG State was HALTING is now INACTIVE
2016-08-29 15:20:57,338 [SwingWorker-pool-2-thread-1] TRACE Move index (1), score (0hard/-128070soft), accepted (true), move (CloudProcess-104 {CloudComputer-89} <-> CloudProcess-295 {CloudComputer-26}).
2016-08-29 15:20:57,338 [SwingWorker-pool-2-thread-1] DEBUG LS step (6730), time spent (3432), score (0hard/-128070soft), best score (0hard/-126690soft), accepted/selected move count (1/2), picked move (CloudProcess-104 {CloudComputer-89} <-> CloudProcess-295 {CloudComputer-26}).
{code}
but without the optaplanner TRACE lines.
Solution proposal A): remove the line "Fire Loop" and put "State was" on trace logging.
Solution proposal B): collapse the 5 lines "Fire Loop" into "5 fire loops" and put "State was" on trace logging.
Solution proposal C): put the line "Fire Loop" and "State was" on trace logging.
I personally dislike this one - even trace logging should still be useful and not more verbose that it needs to be (although it should log in high detail).
This should be fixed for 7.0, 6.5.x and I 'll ask QA to consider adding it for 6.4.x.
> Logging level DEBUG should be less verbose: "Fire Loop" & "State was" should be trace
> -------------------------------------------------------------------------------------
>
> Key: DROOLS-1262
> URL: https://issues.jboss.org/browse/DROOLS-1262
> Project: Drools
> Issue Type: Bug
> Components: core engine
> Affects Versions: 6.4.0.Final, 6.5.0.CR1, 7.0.0.Beta1
> Reporter: Geoffrey De Smet
> Assignee: Mario Fusco
> Priority: Critical
>
> In the latest 6.4 product patches, I am seeing customers that are up to *10 times slower* due to drools in their optaplanner cases. It turns out that they have no logging configuration and many systems - such as WildFly use DEBUG logging by default (often to a file so no one notices it).
> Meanwhile the log fills up with this:
> {code}
> 2016-08-29 15:20:57,338 [SwingWorker-pool-2-thread-1] DEBUG State was INACTIVE is now FIRING_ALL_RULES
> 2016-08-29 15:20:57,338 [SwingWorker-pool-2-thread-1] DEBUG Fire Loop
> 2016-08-29 15:20:57,338 [SwingWorker-pool-2-thread-1] DEBUG Fire Loop
> 2016-08-29 15:20:57,338 [SwingWorker-pool-2-thread-1] DEBUG Fire Loop
> 2016-08-29 15:20:57,338 [SwingWorker-pool-2-thread-1] DEBUG Fire Loop
> 2016-08-29 15:20:57,338 [SwingWorker-pool-2-thread-1] DEBUG Fire Loop
> 2016-08-29 15:20:57,338 [SwingWorker-pool-2-thread-1] DEBUG State was FIRING_ALL_RULES is now HALTING
> 2016-08-29 15:20:57,338 [SwingWorker-pool-2-thread-1] DEBUG State was HALTING is now INACTIVE
> 2016-08-29 15:20:57,338 [SwingWorker-pool-2-thread-1] TRACE Move index (0), score (-10hard/-128070soft), accepted (false), move (CloudProcess-67 {CloudComputer-45} <-> CloudProcess-147 {CloudComputer-18}).
> 2016-08-29 15:20:57,338 [SwingWorker-pool-2-thread-1] DEBUG State was INACTIVE is now FIRING_ALL_RULES
> 2016-08-29 15:20:57,338 [SwingWorker-pool-2-thread-1] DEBUG Fire Loop
> 2016-08-29 15:20:57,338 [SwingWorker-pool-2-thread-1] DEBUG Fire Loop
> 2016-08-29 15:20:57,338 [SwingWorker-pool-2-thread-1] DEBUG Fire Loop
> 2016-08-29 15:20:57,338 [SwingWorker-pool-2-thread-1] DEBUG Fire Loop
> 2016-08-29 15:20:57,338 [SwingWorker-pool-2-thread-1] DEBUG Fire Loop
> 2016-08-29 15:20:57,338 [SwingWorker-pool-2-thread-1] DEBUG State was FIRING_ALL_RULES is now HALTING
> 2016-08-29 15:20:57,338 [SwingWorker-pool-2-thread-1] DEBUG State was HALTING is now INACTIVE
> 2016-08-29 15:20:57,338 [SwingWorker-pool-2-thread-1] TRACE Move index (1), score (0hard/-128070soft), accepted (true), move (CloudProcess-104 {CloudComputer-89} <-> CloudProcess-295 {CloudComputer-26}).
> 2016-08-29 15:20:57,338 [SwingWorker-pool-2-thread-1] DEBUG LS step (6730), time spent (3432), score (0hard/-128070soft), best score (0hard/-126690soft), accepted/selected move count (1/2), picked move (CloudProcess-104 {CloudComputer-89} <-> CloudProcess-295 {CloudComputer-26}).
> {code}
> but without the optaplanner TRACE lines.
> Solution proposal A): remove the line "Fire Loop" and put "State was" on trace logging.
> Solution proposal B): collapse the 5 lines "Fire Loop" into "5 fire loops" and put "State was" on trace logging.
> Solution proposal C): put the line "Fire Loop" and "State was" on trace logging.
> I personally dislike this one - even trace logging should still be useful and not more verbose that it needs to be (although it should log in high detail).
> This should be fixed for 7.0, 6.5.x and I 'll ask QA to consider adding it for 6.4.x.
--
This message was sent by Atlassian JIRA
(v6.4.11#64026)
9 years, 8 months
- 1
- 0
[JBoss JIRA] (DROOLS-1262) Logging level DEBUG should be less verbose: "Fire Loop" & "State was" should be trace
by Geoffrey De Smet (JIRA)
Geoffrey De Smet created DROOLS-1262:
----------------------------------------
Summary: Logging level DEBUG should be less verbose: "Fire Loop" & "State was" should be trace
Key: DROOLS-1262
URL: https://issues.jboss.org/browse/DROOLS-1262
Project: Drools
Issue Type: Bug
Components: core engine
Affects Versions: 7.0.0.Beta1, 6.5.0.CR1, 6.4.0.Final
Reporter: Geoffrey De Smet
Assignee: Mario Fusco
Priority: Critical
In the latest 6.4 product patches, I am seeing customers that are up to 10 times slower due to drools in their optaplanner cases. It turns out that they have no logging configuration and many systems - such as WildFly use DEBUG logging by default (often to a file so no one notices it).
Meanwhile the log fills up with this:
{code}
2016-08-29 15:20:57,338 [SwingWorker-pool-2-thread-1] DEBUG State was INACTIVE is now FIRING_ALL_RULES
2016-08-29 15:20:57,338 [SwingWorker-pool-2-thread-1] DEBUG Fire Loop
2016-08-29 15:20:57,338 [SwingWorker-pool-2-thread-1] DEBUG Fire Loop
2016-08-29 15:20:57,338 [SwingWorker-pool-2-thread-1] DEBUG Fire Loop
2016-08-29 15:20:57,338 [SwingWorker-pool-2-thread-1] DEBUG Fire Loop
2016-08-29 15:20:57,338 [SwingWorker-pool-2-thread-1] DEBUG Fire Loop
2016-08-29 15:20:57,338 [SwingWorker-pool-2-thread-1] DEBUG State was FIRING_ALL_RULES is now HALTING
2016-08-29 15:20:57,338 [SwingWorker-pool-2-thread-1] DEBUG State was HALTING is now INACTIVE
2016-08-29 15:20:57,338 [SwingWorker-pool-2-thread-1] TRACE Move index (0), score (-10hard/-128070soft), accepted (false), move (CloudProcess-67 {CloudComputer-45} <-> CloudProcess-147 {CloudComputer-18}).
2016-08-29 15:20:57,338 [SwingWorker-pool-2-thread-1] DEBUG State was INACTIVE is now FIRING_ALL_RULES
2016-08-29 15:20:57,338 [SwingWorker-pool-2-thread-1] DEBUG Fire Loop
2016-08-29 15:20:57,338 [SwingWorker-pool-2-thread-1] DEBUG Fire Loop
2016-08-29 15:20:57,338 [SwingWorker-pool-2-thread-1] DEBUG Fire Loop
2016-08-29 15:20:57,338 [SwingWorker-pool-2-thread-1] DEBUG Fire Loop
2016-08-29 15:20:57,338 [SwingWorker-pool-2-thread-1] DEBUG Fire Loop
2016-08-29 15:20:57,338 [SwingWorker-pool-2-thread-1] DEBUG State was FIRING_ALL_RULES is now HALTING
2016-08-29 15:20:57,338 [SwingWorker-pool-2-thread-1] DEBUG State was HALTING is now INACTIVE
2016-08-29 15:20:57,338 [SwingWorker-pool-2-thread-1] TRACE Move index (1), score (0hard/-128070soft), accepted (true), move (CloudProcess-104 {CloudComputer-89} <-> CloudProcess-295 {CloudComputer-26}).
2016-08-29 15:20:57,338 [SwingWorker-pool-2-thread-1] DEBUG LS step (6730), time spent (3432), score (0hard/-128070soft), best score (0hard/-126690soft), accepted/selected move count (1/2), picked move (CloudProcess-104 {CloudComputer-89} <-> CloudProcess-295 {CloudComputer-26}).
{code}
but without the optaplanner TRACE lines.
Solution proposal A): remove the line "Fire Loop" and put "State was" on trace logging.
Solution proposal B): collapse the 5 lines "Fire Loop" into "5 fire loops" and put "State was" on trace logging.
Solution proposal C): put the line "Fire Loop" and "State was" on trace logging.
I personally dislike this one - even trace logging should still be useful and not more verbose that it needs to be (although it should log in high detail).
This should be fixed for 7.0, 6.5.x and I 'll ask QA to consider adding it for 6.4.x.
--
This message was sent by Atlassian JIRA
(v6.4.11#64026)
9 years, 8 months
- 1
- 0
[JBoss JIRA] (WFCORE-1235) Multiple triggers of each activator service when there are multiple modules with different service activator files in an ear.
by RH Bugzilla Integration (JIRA)
[ https://issues.jboss.org/browse/WFCORE-1235?page=com.atlassian.jira.plugi... ]
RH Bugzilla Integration commented on WFCORE-1235:
-------------------------------------------------
Peter Mackay <pmackay(a)redhat.com> changed the Status of [bug 1286272|https://bugzilla.redhat.com/show_bug.cgi?id=1286272] from ON_QA to VERIFIED
> Multiple triggers of each activator service when there are multiple modules with different service activator files in an ear.
> -----------------------------------------------------------------------------------------------------------------------------
>
> Key: WFCORE-1235
> URL: https://issues.jboss.org/browse/WFCORE-1235
> Project: WildFly Core
> Issue Type: Bug
> Reporter: Panagiotis Sotiropoulos
> Assignee: Panagiotis Sotiropoulos
> Priority: Blocker
> Labels: downstream_dependency
>
> Description of problem:
> If one EAR contains more than one module with a META-INF/services/org.jboss.msc.service.ServiceActivator file the services are activated multiple times (as ServiceActivator files are found).
--
This message was sent by Atlassian JIRA
(v6.4.11#64026)
9 years, 8 months
- 1
- 0
[JBoss JIRA] (JBJCA-1328) Communications link failure - unable to create valid connections
by Jesper Pedersen (JIRA)
[ https://issues.jboss.org/browse/JBJCA-1328?page=com.atlassian.jira.plugin... ]
Jesper Pedersen reassigned JBJCA-1328:
--------------------------------------
Assignee: Stefano Maestri (was: Jesper Pedersen)
> Communications link failure - unable to create valid connections
> ----------------------------------------------------------------
>
> Key: JBJCA-1328
> URL: https://issues.jboss.org/browse/JBJCA-1328
> Project: IronJacamar
> Issue Type: Bug
> Components: JDBC, Standalone, Validator
> Environment: Server: Wildfly 10
> OS: CentOS 7
> Database: MySQL 5.7.14
> Reporter: Oscar Calderon
> Assignee: Stefano Maestri
>
> There's a connection pool configured in Wildfly 10 to connect to MySQL database. A Spring REST app is deployed and uses the connection pool. Problem is, it looks like it maintains the opened connections like they were alive, but when DB timeout passes and application requests a connection from pool, it fails with the next error:
> {{code}}
> 2016-08-20 10:05:05,484 DEBUG [org.hibernate.engine.jdbc.spi.SqlExceptionHelper] (default task-17) could not extract ResultSet [n/a]: com.mysql.jdbc.exceptions.jdbc4.CommunicationsException: Communications link failure
> The last packet successfully received from the server was 3,999,184 milliseconds ago. The last packet sent successfully to the server was 47 milliseconds ago.
> at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
> at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:62)
> at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
> at java.lang.reflect.Constructor.newInstance(Constructor.java:423)
> at com.mysql.jdbc.Util.handleNewInstance(Util.java:404)
> at com.mysql.jdbc.SQLError.createCommunicationsException(SQLError.java:988)
> at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:3552)
> at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:3452)
> at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:3893)
> at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:2526)
> at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:2673)
> at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2549)
> at com.mysql.jdbc.PreparedStatement.executeInternal(PreparedStatement.java:1861)
> at com.mysql.jdbc.PreparedStatement.executeQuery(PreparedStatement.java:1962)
> at org.jboss.jca.adapters.jdbc.WrappedPreparedStatement.executeQuery(WrappedPreparedStatement.java:504)
> at org.hibernate.engine.jdbc.internal.ResultSetReturnImpl.extract(ResultSetReturnImpl.java:70)
> at org.hibernate.loader.Loader.getResultSet(Loader.java:2117)
> at org.hibernate.loader.Loader.executeQueryStatement(Loader.java:1905)
> at org.hibernate.loader.Loader.executeQueryStatement(Loader.java:1881)
> at org.hibernate.loader.Loader.doQuery(Loader.java:926)
> at org.hibernate.loader.Loader.doQueryAndInitializeNonLazyCollections(Loader.java:343)
> at org.hibernate.loader.Loader.doList(Loader.java:2609)
> at org.hibernate.loader.Loader.doList(Loader.java:2592)
> at org.hibernate.loader.Loader.listIgnoreQueryCache(Loader.java:2424)
> at org.hibernate.loader.Loader.list(Loader.java:2419)
> at org.hibernate.loader.hql.QueryLoader.list(QueryLoader.java:502)
> at org.hibernate.hql.internal.ast.QueryTranslatorImpl.list(QueryTranslatorImpl.java:371)
> at org.hibernate.engine.query.spi.HQLQueryPlan.performList(HQLQueryPlan.java:216)
> at org.hibernate.internal.SessionImpl.list(SessionImpl.java:1450)
> at org.hibernate.query.internal.AbstractProducedQuery.doList(AbstractProducedQuery.java:1402)
> at org.hibernate.query.internal.AbstractProducedQuery.list(AbstractProducedQuery.java:1374)
> at org.hibernate.query.internal.AbstractProducedQuery.getSingleResult(AbstractProducedQuery.java:1420)
> at com.hayturno.spring.dao.PacienteDAO.getPatientInfo(PacienteDAO.java:28)
> at com.hayturno.spring.service.AuthorizationService.isValidUser(AuthorizationService.java:29)
> at com.hayturno.spring.controller.BaseController.authorizeUser(BaseController.java:41)
> at com.hayturno.spring.controller.DoctorController.getDoctorsList(DoctorController.java:34)
> at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
> at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
> at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
> at java.lang.reflect.Method.invoke(Method.java:498)
> at org.springframework.web.method.support.InvocableHandlerMethod.doInvoke(InvocableHandlerMethod.java:221)
> at org.springframework.web.method.support.InvocableHandlerMethod.invokeForRequest(InvocableHandlerMethod.java:136)
> at org.springframework.web.servlet.mvc.method.annotation.ServletInvocableHandlerMethod.invokeAndHandle(ServletInvocableHandlerMethod.java:114)
> at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.invokeHandlerMethod(RequestMappingHandlerAdapter.java:827)
> at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.handleInternal(RequestMappingHandlerAdapter.java:738)
> at org.springframework.web.servlet.mvc.method.AbstractHandlerMethodAdapter.handle(AbstractHandlerMethodAdapter.java:85)
> at org.springframework.web.servlet.DispatcherServlet.doDispatch(DispatcherServlet.java:963)
> at org.springframework.web.servlet.DispatcherServlet.doService(DispatcherServlet.java:897)
> at org.springframework.web.servlet.FrameworkServlet.processRequest(FrameworkServlet.java:970)
> at org.springframework.web.servlet.FrameworkServlet.doPost(FrameworkServlet.java:872)
> at javax.servlet.http.HttpServlet.service(HttpServlet.java:707)
> at org.springframework.web.servlet.FrameworkServlet.service(FrameworkServlet.java:846)
> at javax.servlet.http.HttpServlet.service(HttpServlet.java:790)
> at io.undertow.servlet.handlers.ServletHandler.handleRequest(ServletHandler.java:85)
> at io.undertow.servlet.handlers.security.ServletSecurityRoleHandler.handleRequest(ServletSecurityRoleHandler.java:62)
> at io.undertow.servlet.handlers.ServletDispatchingHandler.handleRequest(ServletDispatchingHandler.java:36)
> at org.wildfly.extension.undertow.security.SecurityContextAssociationHandler.handleRequest(SecurityContextAssociationHandler.java:78)
> at io.undertow.server.handlers.PredicateHandler.handleRequest(PredicateHandler.java:43)
> at io.undertow.servlet.handlers.security.SSLInformationAssociationHandler.handleRequest(SSLInformationAssociationHandler.java:131)
> at io.undertow.servlet.handlers.security.ServletAuthenticationCallHandler.handleRequest(ServletAuthenticationCallHandler.java:57)
> at io.undertow.server.handlers.PredicateHandler.handleRequest(PredicateHandler.java:43)
> at io.undertow.security.handlers.AbstractConfidentialityHandler.handleRequest(AbstractConfidentialityHandler.java:46)
> at io.undertow.servlet.handlers.security.ServletConfidentialityConstraintHandler.handleRequest(ServletConfidentialityConstraintHandler.java:64)
> at io.undertow.security.handlers.AuthenticationMechanismsHandler.handleRequest(AuthenticationMechanismsHandler.java:60)
> at io.undertow.servlet.handlers.security.CachedAuthenticatedSessionHandler.handleRequest(CachedAuthenticatedSessionHandler.java:77)
> at io.undertow.security.handlers.NotificationReceiverHandler.handleRequest(NotificationReceiverHandler.java:50)
> at io.undertow.security.handlers.AbstractSecurityContextAssociationHandler.handleRequest(AbstractSecurityContextAssociationHandler.java:43)
> at io.undertow.server.handlers.PredicateHandler.handleRequest(PredicateHandler.java:43)
> at org.wildfly.extension.undertow.security.jacc.JACCContextIdHandler.handleRequest(JACCContextIdHandler.java:61)
> at io.undertow.server.handlers.PredicateHandler.handleRequest(PredicateHandler.java:43)
> at io.undertow.server.handlers.PredicateHandler.handleRequest(PredicateHandler.java:43)
> at io.undertow.servlet.handlers.ServletInitialHandler.handleFirstRequest(ServletInitialHandler.java:284)
> at io.undertow.servlet.handlers.ServletInitialHandler.dispatchRequest(ServletInitialHandler.java:263)
> at io.undertow.servlet.handlers.ServletInitialHandler.access$000(ServletInitialHandler.java:81)
> at io.undertow.servlet.handlers.ServletInitialHandler$1.handleRequest(ServletInitialHandler.java:174)
> at io.undertow.server.Connectors.executeRootHandler(Connectors.java:202)
> at io.undertow.server.HttpServerExchange$1.run(HttpServerExchange.java:793)
> at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
> at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
> at java.lang.Thread.run(Thread.java:745)
> Caused by: java.io.EOFException: Can not read response from server. Expected to read 4 bytes, read 0 bytes before connection was unexpectedly lost.
> at com.mysql.jdbc.MysqlIO.readFully(MysqlIO.java:3004)
> at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:3462)
> ... 73 more
> 2016-08-20 10:05:05,488 WARN [org.hibernate.engine.jdbc.spi.SqlExceptionHelper] (default task-17) SQL Error: 0, SQLState: 08S01
> 2016-08-20 10:05:05,488 ERROR [org.hibernate.engine.jdbc.spi.SqlExceptionHelper] (default task-17) Communications link failure
> The last packet successfully received from the server was 3,999,184 milliseconds ago. The last packet sent successfully to the server was 47 milliseconds ago.
> 2016-08-20 10:05:05,493 DEBUG [org.hibernate.resource.jdbc.internal.ResourceRegistryStandardImpl] (default task-17) Exception clearing maxRows/queryTimeout [No operations allowed after statement closed.]
> 2016-08-20 10:05:05,499 DEBUG [org.hibernate.resource.transaction.backend.jdbc.internal.JdbcResourceLocalTransactionCoordinatorImpl] (default task-17) JDBC transaction marked for rollback-only (exception provided for stack trace): java.lang.Exception: exception just for purpose of providing stack trace
> at org.hibernate.resource.transaction.backend.jdbc.internal.JdbcResourceLocalTransactionCoordinatorImpl$TransactionDriverControlImpl.markRollbackOnly(JdbcResourceLocalTransactionCoordinatorImpl.java:254)
> at org.hibernate.engine.transaction.internal.TransactionImpl.setRollbackOnly(TransactionImpl.java:143)
> at org.hibernate.Transaction.markRollbackOnly(Transaction.java:68)
> at org.hibernate.internal.AbstractSharedSessionContract.markForRollbackOnly(AbstractSharedSessionContract.java:340)
> at org.hibernate.internal.ExceptionConverterImpl.handlePersistenceException(ExceptionConverterImpl.java:271)
> at org.hibernate.internal.ExceptionConverterImpl.convert(ExceptionConverterImpl.java:148)
> at org.hibernate.internal.ExceptionConverterImpl.convert(ExceptionConverterImpl.java:155)
> at org.hibernate.query.internal.AbstractProducedQuery.list(AbstractProducedQuery.java:1383)
> at org.hibernate.query.internal.AbstractProducedQuery.getSingleResult(AbstractProducedQuery.java:1420)
> at com.hayturno.spring.dao.PacienteDAO.getPatientInfo(PacienteDAO.java:28)
> at com.hayturno.spring.service.AuthorizationService.isValidUser(AuthorizationService.java:29)
> at com.hayturno.spring.controller.BaseController.authorizeUser(BaseController.java:41)
> at com.hayturno.spring.controller.DoctorController.getDoctorsList(DoctorController.java:34)
> at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
> at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
> at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
> at java.lang.reflect.Method.invoke(Method.java:498)
> at org.springframework.web.method.support.InvocableHandlerMethod.doInvoke(InvocableHandlerMethod.java:221)
> at org.springframework.web.method.support.InvocableHandlerMethod.invokeForRequest(InvocableHandlerMethod.java:136)
> at org.springframework.web.servlet.mvc.method.annotation.ServletInvocableHandlerMethod.invokeAndHandle(ServletInvocableHandlerMethod.java:114)
> at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.invokeHandlerMethod(RequestMappingHandlerAdapter.java:827)
> at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.handleInternal(RequestMappingHandlerAdapter.java:738)
> at org.springframework.web.servlet.mvc.method.AbstractHandlerMethodAdapter.handle(AbstractHandlerMethodAdapter.java:85)
> at org.springframework.web.servlet.DispatcherServlet.doDispatch(DispatcherServlet.java:963)
> at org.springframework.web.servlet.DispatcherServlet.doService(DispatcherServlet.java:897)
> at org.springframework.web.servlet.FrameworkServlet.processRequest(FrameworkServlet.java:970)
> at org.springframework.web.servlet.FrameworkServlet.doPost(FrameworkServlet.java:872)
> at javax.servlet.http.HttpServlet.service(HttpServlet.java:707)
> at org.springframework.web.servlet.FrameworkServlet.service(FrameworkServlet.java:846)
> at javax.servlet.http.HttpServlet.service(HttpServlet.java:790)
> at io.undertow.servlet.handlers.ServletHandler.handleRequest(ServletHandler.java:85)
> at io.undertow.servlet.handlers.security.ServletSecurityRoleHandler.handleRequest(ServletSecurityRoleHandler.java:62)
> at io.undertow.servlet.handlers.ServletDispatchingHandler.handleRequest(ServletDispatchingHandler.java:36)
> at org.wildfly.extension.undertow.security.SecurityContextAssociationHandler.handleRequest(SecurityContextAssociationHandler.java:78)
> at io.undertow.server.handlers.PredicateHandler.handleRequest(PredicateHandler.java:43)
> at io.undertow.servlet.handlers.security.SSLInformationAssociationHandler.handleRequest(SSLInformationAssociationHandler.java:131)
> at io.undertow.servlet.handlers.security.ServletAuthenticationCallHandler.handleRequest(ServletAuthenticationCallHandler.java:57)
> at io.undertow.server.handlers.PredicateHandler.handleRequest(PredicateHandler.java:43)
> at io.undertow.security.handlers.AbstractConfidentialityHandler.handleRequest(AbstractConfidentialityHandler.java:46)
> at io.undertow.servlet.handlers.security.ServletConfidentialityConstraintHandler.handleRequest(ServletConfidentialityConstraintHandler.java:64)
> at io.undertow.security.handlers.AuthenticationMechanismsHandler.handleRequest(AuthenticationMechanismsHandler.java:60)
> at io.undertow.servlet.handlers.security.CachedAuthenticatedSessionHandler.handleRequest(CachedAuthenticatedSessionHandler.java:77)
> at io.undertow.security.handlers.NotificationReceiverHandler.handleRequest(NotificationReceiverHandler.java:50)
> at io.undertow.security.handlers.AbstractSecurityContextAssociationHandler.handleRequest(AbstractSecurityContextAssociationHandler.java:43)
> at io.undertow.server.handlers.PredicateHandler.handleRequest(PredicateHandler.java:43)
> at org.wildfly.extension.undertow.security.jacc.JACCContextIdHandler.handleRequest(JACCContextIdHandler.java:61)
> at io.undertow.server.handlers.PredicateHandler.handleRequest(PredicateHandler.java:43)
> at io.undertow.server.handlers.PredicateHandler.handleRequest(PredicateHandler.java:43)
> at io.undertow.servlet.handlers.ServletInitialHandler.handleFirstRequest(ServletInitialHandler.java:284)
> at io.undertow.servlet.handlers.ServletInitialHandler.dispatchRequest(ServletInitialHandler.java:263)
> at io.undertow.servlet.handlers.ServletInitialHandler.access$000(ServletInitialHandler.java:81)
> at io.undertow.servlet.handlers.ServletInitialHandler$1.handleRequest(ServletInitialHandler.java:174)
> at io.undertow.server.Connectors.executeRootHandler(Connectors.java:202)
> at io.undertow.server.HttpServerExchange$1.run(HttpServerExchange.java:793)
> at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
> at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
> at java.lang.Thread.run(Thread.java:745)
> {{code}}
> Looking above this, we have the next output from JCA:
> {{code}}
> 2016-08-20 08:59:21,290 DEBUG [org.jboss.ejb.client.txn] (Periodic Recovery) Send recover request for transaction origin node identifier 1 to EJB receiver with node name centos-2gb-nyc1-01
> 2016-08-20 08:59:31,292 DEBUG [org.jboss.ejb.client.txn] (Periodic Recovery) Send recover request for transaction origin node identifier 1 to EJB receiver with node name centos-2gb-nyc1-01
> 2016-08-20 09:00:13,707 DEBUG [org.jboss.jca.core.connectionmanager.pool.idle.IdleRemover] (IdleRemover) Notifying pools, interval: 150000
> 2016-08-20 09:00:13,707 DEBUG [org.jboss.jca.core.connectionmanager.pool.validator.ConnectionValidator] (ConnectionValidator) Notifying pools, interval: 150000
> 2016-08-20 09:00:13,708 DEBUG [org.jboss.jca.core.connectionmanager.pool.strategy.OnePool] (IdleRemover) HayTurno3DS: removeIdleConnections(1471704913708) [2/30]
> 2016-08-20 09:01:31,296 DEBUG [org.jboss.ejb.client.txn] (Periodic Recovery) Send recover request for transaction origin node identifier 1 to EJB receiver with node name centos-2gb-nyc1-01
> 2016-08-20 09:01:41,298 DEBUG [org.jboss.ejb.client.txn] (Periodic Recovery) Send recover request for transaction origin node identifier 1 to EJB receiver with node name centos-2gb-nyc1-01
> 2016-08-20 09:02:43,709 DEBUG [org.jboss.jca.core.connectionmanager.pool.validator.ConnectionValidator] (ConnectionValidator) Notifying pools, interval: 150000
> 2016-08-20 09:02:43,709 DEBUG [org.jboss.jca.core.connectionmanager.pool.idle.IdleRemover] (IdleRemover) Notifying pools, interval: 150000
> 2016-08-20 09:02:43,711 DEBUG [org.jboss.jca.core.connectionmanager.pool.strategy.OnePool] (IdleRemover) HayTurno3DS: removeIdleConnections(1471705063710) [2/30]
> 2016-08-20 09:03:41,302 DEBUG [org.jboss.ejb.client.txn] (Periodic Recovery) Send recover request for transaction origin node identifier 1 to EJB receiver with node name centos-2gb-nyc1-01
> 2016-08-20 09:03:51,304 DEBUG [org.jboss.ejb.client.txn] (Periodic Recovery) Send recover request for transaction origin node identifier 1 to EJB receiver with node name centos-2gb-nyc1-01
> 2016-08-20 09:05:13,712 DEBUG [org.jboss.jca.core.connectionmanager.pool.idle.IdleRemover] (IdleRemover) Notifying pools, interval: 150000
> 2016-08-20 09:05:13,712 DEBUG [org.jboss.jca.core.connectionmanager.pool.validator.ConnectionValidator] (ConnectionValidator) Notifying pools, interval: 150000
> 2016-08-20 09:05:13,716 DEBUG [org.jboss.jca.core.connectionmanager.pool.strategy.OnePool] (IdleRemover) HayTurno3DS: removeIdleConnections(1471705213715) [2/30]
> 2016-08-20 09:05:51,307 DEBUG [org.jboss.ejb.client.txn] (Periodic Recovery) Send recover request for transaction origin node identifier 1 to EJB receiver with node name centos-2gb-nyc1-01
> 2016-08-20 09:06:01,308 DEBUG [org.jboss.ejb.client.txn] (Periodic Recovery) Send recover request for transaction origin node identifier 1 to EJB receiver with node name centos-2gb-nyc1-01
> 2016-08-20 09:07:43,716 DEBUG [org.jboss.jca.core.connectionmanager.pool.validator.ConnectionValidator] (ConnectionValidator) Notifying pools, interval: 150000
> 2016-08-20 09:07:43,717 DEBUG [org.jboss.jca.core.connectionmanager.pool.idle.IdleRemover] (IdleRemover) Notifying pools, interval: 150000
> 2016-08-20 09:07:43,717 DEBUG [org.jboss.jca.core.connectionmanager.pool.strategy.OnePool] (IdleRemover) HayTurno3DS: removeIdleConnections(1471705363717) [2/30]
> 2016-08-20 09:08:01,310 DEBUG [org.jboss.ejb.client.txn] (Periodic Recovery) Send recover request for transaction origin node identifier 1 to EJB receiver with node name centos-2gb-nyc1-01
> 2016-08-20 09:08:11,312 DEBUG [org.jboss.ejb.client.txn] (Periodic Recovery) Send recover request for transaction origin node identifier 1 to EJB receiver with node name centos-2gb-nyc1-01
> 2016-08-20 09:10:11,315 DEBUG [org.jboss.ejb.client.txn] (Periodic Recovery) Send recover request for transaction origin node identifier 1 to EJB receiver with node name centos-2gb-nyc1-01
> 2016-08-20 09:10:13,718 DEBUG [org.jboss.jca.core.connectionmanager.pool.idle.IdleRemover] (IdleRemover) Notifying pools, interval: 150000
> 2016-08-20 09:10:13,718 DEBUG [org.jboss.jca.core.connectionmanager.pool.validator.ConnectionValidator] (ConnectionValidator) Notifying pools, interval: 150000
> 2016-08-20 09:10:13,718 DEBUG [org.jboss.jca.core.connectionmanager.pool.strategy.OnePool] (IdleRemover) HayTurno3DS: removeIdleConnections(1471705513718) [2/30]
> 2016-08-20 09:10:21,318 DEBUG [org.jboss.ejb.client.txn] (Periodic Recovery) Send recover request for transaction origin node identifier 1 to EJB receiver with node name centos-2gb-nyc1-01
> 2016-08-20 09:12:21,322 DEBUG [org.jboss.ejb.client.txn] (Periodic Recovery) Send recover request for transaction origin node identifier 1 to EJB receiver with node name centos-2gb-nyc1-01
> 2016-08-20 09:12:31,324 DEBUG [org.jboss.ejb.client.txn] (Periodic Recovery) Send recover request for transaction origin node identifier 1 to EJB receiver with node name centos-2gb-nyc1-01
> 2016-08-20 09:12:43,719 DEBUG [org.jboss.jca.core.connectionmanager.pool.idle.IdleRemover] (IdleRemover) Notifying pools, interval: 150000
> 2016-08-20 09:12:43,719 DEBUG [org.jboss.jca.core.connectionmanager.pool.validator.ConnectionValidator] (ConnectionValidator) Notifying pools, interval: 150000
> 2016-08-20 09:12:43,719 DEBUG [org.jboss.jca.core.connectionmanager.pool.strategy.OnePool] (IdleRemover) HayTurno3DS: removeIdleConnections(1471705663719) [2/30]
> 2016-08-20 09:14:31,328 DEBUG [org.jboss.ejb.client.txn] (Periodic Recovery) Send recover request for transaction origin node identifier 1 to EJB receiver with node name centos-2gb-nyc1-01
> 2016-08-20 09:14:41,331 DEBUG [org.jboss.ejb.client.txn] (Periodic Recovery) Send recover request for transaction origin node identifier 1 to EJB receiver with node name centos-2gb-nyc1-01
> 2016-08-20 09:15:13,720 DEBUG [org.jboss.jca.core.connectionmanager.pool.idle.IdleRemover] (IdleRemover) Notifying pools, interval: 150000
> 2016-08-20 09:15:13,722 DEBUG [org.jboss.jca.core.connectionmanager.pool.strategy.OnePool] (IdleRemover) HayTurno3DS: removeIdleConnections(1471705813721) [2/30]
> 2016-08-20 09:15:13,720 DEBUG [org.jboss.jca.core.connectionmanager.pool.validator.ConnectionValidator] (ConnectionValidator) Notifying pools, interval: 150000
> 2016-08-20 09:16:41,334 DEBUG [org.jboss.ejb.client.txn] (Periodic Recovery) Send recover request for transaction origin node identifier 1 to EJB receiver with node name centos-2gb-nyc1-01
> 2016-08-20 09:16:51,336 DEBUG [org.jboss.ejb.client.txn] (Periodic Recovery) Send recover request for transaction origin node identifier 1 to EJB receiver with node name centos-2gb-nyc1-01
> 2016-08-20 09:17:43,723 DEBUG [org.jboss.jca.core.connectionmanager.pool.idle.IdleRemover] (IdleRemover) Notifying pools, interval: 150000
> 2016-08-20 09:17:43,724 DEBUG [org.jboss.jca.core.connectionmanager.pool.strategy.OnePool] (IdleRemover) HayTurno3DS: removeIdleConnections(1471705963724) [2/30]
> 2016-08-20 09:17:43,724 DEBUG [org.jboss.jca.core.connectionmanager.pool.validator.ConnectionValidator] (ConnectionValidator) Notifying pools, interval: 150000
> 2016-08-20 09:18:51,340 DEBUG [org.jboss.ejb.client.txn] (Periodic Recovery) Send recover request for transaction origin node identifier 1 to EJB receiver with node name centos-2gb-nyc1-01
> 2016-08-20 09:19:01,342 DEBUG [org.jboss.ejb.client.txn] (Periodic Recovery) Send recover request for transaction origin node identifier 1 to EJB receiver with node name centos-2gb-nyc1-01
> 2016-08-20 09:20:13,725 DEBUG [org.jboss.jca.core.connectionmanager.pool.validator.ConnectionValidator] (ConnectionValidator) Notifying pools, interval: 150000
> 2016-08-20 09:20:13,725 DEBUG [org.jboss.jca.core.connectionmanager.pool.idle.IdleRemover] (IdleRemover) Notifying pools, interval: 150000
> 2016-08-20 09:20:13,727 DEBUG [org.jboss.jca.core.connectionmanager.pool.strategy.OnePool] (IdleRemover) HayTurno3DS: removeIdleConnections(1471706113727) [2/30]
> ...
> {{code}}
> It looks like pool validates idle connections and kills the idle ones and it should create new ones, but it doesn´t work. Why it cannot have valid connections? Also, from where does it get 150000 interval?
--
This message was sent by Atlassian JIRA
(v6.4.11#64026)
9 years, 8 months
- 1
- 0