org.evosuite.runtime.TooManyResourcesException: Loop has been executed more times than the allowed 10000

[jesus-gorronogoitia]

Characteristics

• Issue Type: test report
• Reproducibility: always
• Severity: major
• Tool/Service/Component: Botsing-reproduction 1.0.8_SNAPSHOT
• Execution Environment: CentOS 7
• Reporter: Jesús Gorroñogoitiajesus.gorronogoitia@atos.net

Description

Experiment running Botsing reproduction v1.0.8_snapshot on Atos IF runtime exception is not generating crash-reproduction tests. See execution logs here.
Inspection of logs shows that Botsing is triggering an rg.evosuite.runtime.TooManyResourcesException: Loop has been executed more times than the allowed 10000 exception when executing the best generated test.
This is an excerpt of Botsing logs:

13:09:00.852 [main] DEBUG e.s.b.t.s.BotsingIndividualStrategy - Fitness calculation ... 
13:09:00.853 [main] DEBUG e.s.b.t.s.BotsingIndividualStrategy - Fitness Function: 4.5
13:09:00.853 [main] DEBUG e.s.b.t.s.BotsingIndividualStrategy - Fitness calculation ... 
13:09:00.853 [main] DEBUG e.s.b.t.s.BotsingIndividualStrategy - Fitness Function: 4.5
13:09:00.857 [main] DEBUG e.s.b.g.s.GuidedGeneticAlgorithm - Replace parents
13:09:00.857 [main] DEBUG e.s.b.g.s.GuidedGeneticAlgorithm - Current value of stopping condition class org.evosuite.ga.stoppingconditio
ns.ZeroFitnessStoppingCondition: 5
13:09:00.857 [main] DEBUG e.s.b.g.s.GuidedGeneticAlgorithm - Current value of stopping condition class org.evosuite.ga.stoppingconditio
ns.MaxTimeStoppingCondition: 9
13:09:00.857 [main] DEBUG e.s.b.g.s.GuidedGeneticAlgorithm - Generating offspring
13:09:00.861 [main] DEBUG e.s.b.t.s.BotsingIndividualStrategy - Fitness calculation ... 
13:09:00.861 [main] DEBUG e.s.b.t.s.BotsingIndividualStrategy - Fitness Function: 4.5
13:09:00.882 [main] DEBUG e.s.b.t.s.BotsingIndividualStrategy - Fitness calculation ... 
13:09:00.882 [main] DEBUG e.s.b.t.s.BotsingIndividualStrategy - Fitness Function: 4.5
13:09:00.888 [main] DEBUG e.s.b.g.s.GuidedGeneticAlgorithm - Keep parents
13:09:00.888 [main] DEBUG e.s.b.g.s.GuidedGeneticAlgorithm - Sort current population.
13:09:01.364 [main] DEBUG e.s.b.t.s.BotsingIndividualStrategy - Fitness calculation ... 
13:09:01.364 [main] DEBUG e.s.b.t.s.BotsingIndividualStrategy - Fitness Function: 4.5
13:09:01.365 [main] DEBUG e.s.b.g.s.GuidedGeneticAlgorithm - *  The best generated test is: IFAuthenticationManager iFAuthenticationMan
ager0 = new IFAuthenticationManager();
IFAuthenticationManager iFAuthenticationManager1 = new IFAuthenticationManager();
IFAuthenticationManager.access$000();
String string0 = "";
User user0 = iFAuthenticationManager0.getUser(string0);
iFAuthenticationManager0.deleteUser(user0);
13:09:01.365 [main] DEBUG e.s.b.g.s.GuidedGeneticAlgorithm - 1 thrown exception(s) are detected in the best test case: 
13:09:01.365 [main] DEBUG e.s.b.g.s.GuidedGeneticAlgorithm - org.evosuite.runtime.TooManyResourcesException: Loop has been executed more times than the allowed 10000
13:09:01.365 [main] DEBUG e.s.b.g.s.GuidedGeneticAlgorithm - org.evosuite.runtime.LoopCounter.checkLoop(LoopCounter.java:116)
13:09:01.365 [main] DEBUG e.s.b.g.s.GuidedGeneticAlgorithm - com.ctc.wstx.io.UTF8Reader.read(UTF8Reader.java:151)
13:09:01.365 [main] DEBUG e.s.b.g.s.GuidedGeneticAlgorithm - com.ctc.wstx.io.ReaderSource.readInto(ReaderSource.java:84)
13:09:01.365 [main] DEBUG e.s.b.g.s.GuidedGeneticAlgorithm - com.ctc.wstx.io.BranchingReaderSource.readInto(BranchingReaderSource.java:57)
13:09:01.365 [main] DEBUG e.s.b.g.s.GuidedGeneticAlgorithm - com.ctc.wstx.sr.StreamScanner.loadMoreFromCurrent(StreamScanner.java:1046)
13:09:01.365 [main] DEBUG e.s.b.g.s.GuidedGeneticAlgorithm - com.ctc.wstx.sr.StreamScanner.loadMoreFromCurrent(StreamScanner.java:1053)
13:09:01.365 [main] DEBUG e.s.b.g.s.GuidedGeneticAlgorithm - com.ctc.wstx.sr.StreamScanner.getNextCharFromCurrent(StreamScanner.java:811)
13:09:01.365 [main] DEBUG e.s.b.g.s.GuidedGeneticAlgorithm - com.ctc.wstx.sr.BasicStreamReader.readComment2(BasicStreamReader.java:3839)
13:09:01.365 [main] DEBUG e.s.b.g.s.GuidedGeneticAlgorithm - com.ctc.wstx.sr.BasicStreamReader.readComment(BasicStreamReader.java:3825)
13:09:01.365 [main] DEBUG e.s.b.g.s.GuidedGeneticAlgorithm - com.ctc.wstx.sr.BasicStreamReader.finishToken(BasicStreamReader.java:3724)
13:09:01.365 [main] DEBUG e.s.b.g.s.GuidedGeneticAlgorithm - com.ctc.wstx.sr.BasicStreamReader.safeFinishToken(BasicStreamReader.java:3649)
13:09:01.365 [main] DEBUG e.s.b.g.s.GuidedGeneticAlgorithm - com.ctc.wstx.sr.BasicStreamReader.getText(BasicStreamReader.java:809)
13:09:01.365 [main] DEBUG e.s.b.g.s.GuidedGeneticAlgorithm - org.apache.axiom.util.stax.wrapper.XMLStreamReaderWrapper.getText(XMLStreamReaderWrapper.java:164)
13:09:01.365 [main] DEBUG e.s.b.g.s.GuidedGeneticAlgorithm - org.apache.axiom.om.impl.builder.StAXOMBuilder.createComment(StAXOMBuilder.java:477)
13:09:01.365 [main] DEBUG e.s.b.g.s.GuidedGeneticAlgorithm - org.apache.axiom.om.impl.builder.StAXOMBuilder.next(StAXOMBuilder.java:280)
13:09:01.365 [main] DEBUG e.s.b.g.s.GuidedGeneticAlgorithm - org.apache.axiom.om.impl.llom.OMSerializableImpl.build(OMSerializableImpl.java:78)
13:09:01.365 [main] DEBUG e.s.b.g.s.GuidedGeneticAlgorithm - org.apache.axiom.om.impl.llom.OMElementImpl.build(OMElementImpl.java:721)
13:09:01.365 [main] DEBUG e.s.b.g.s.GuidedGeneticAlgorithm - org.apache.axis2.util.XMLUtils.toOM(XMLUtils.java:595)
13:09:01.365 [main] DEBUG e.s.b.g.s.GuidedGeneticAlgorithm - org.apache.axis2.util.XMLUtils.toOM(XMLUtils.java:575)
13:09:01.365 [main] DEBUG e.s.b.g.s.GuidedGeneticAlgorithm - org.apache.axis2.deployment.DescriptionBuilder.buildOM(DescriptionBuilder.java:97)
13:09:01.365 [main] DEBUG e.s.b.g.s.GuidedGeneticAlgorithm - org.apache.axis2.deployment.AxisConfigBuilder.populateConfig(AxisConfigBuilder.java:89)
13:09:01.365 [main] DEBUG e.s.b.g.s.GuidedGeneticAlgorithm - org.apache.axis2.deployment.DeploymentEngine.populateAxisConfiguration(DeploymentEngine.java:857)
13:09:01.365 [main] DEBUG e.s.b.g.s.GuidedGeneticAlgorithm - org.apache.axis2.deployment.FileSystemConfigurator.getAxisConfiguration(FileSystemConfigurator.java:116)
13:09:01.365 [main] DEBUG e.s.b.g.s.GuidedGeneticAlgorithm - org.apache.axis2.context.ConfigurationContextFactory.createConfigurationContext(ConfigurationContextFactory.java:64)
13:09:01.365 [main] DEBUG e.s.b.g.s.GuidedGeneticAlgorithm - org.apache.axis2.context.ConfigurationContextFactory.createConfigurationContextFromFileSystem(ConfigurationContextFactory.java:210)
13:09:01.365 [main] DEBUG e.s.b.g.s.GuidedGeneticAlgorithm - org.apache.axis2.client.ServiceClient.configureServiceClient(ServiceClient.java:151)
13:09:01.365 [main] DEBUG e.s.b.g.s.GuidedGeneticAlgorithm - org.apache.axis2.client.ServiceClient.<init>(ServiceClient.java:144)
13:09:01.365 [main] DEBUG e.s.b.g.s.GuidedGeneticAlgorithm - org.wso2.carbon.um.ws.api.stub.RemoteUserStoreManagerServiceStub.<init>(RemoteUserStoreManagerServiceStub.java:639)
13:09:01.365 [main] DEBUG e.s.b.g.s.GuidedGeneticAlgorithm - org.wso2.carbon.um.ws.api.stub.RemoteUserStoreManagerServiceStub.<init>(RemoteUserStoreManagerServiceStub.java:625)
13:09:01.365 [main] DEBUG e.s.b.g.s.GuidedGeneticAlgorithm - eu.supersede.integration.api.security.IFUserStoreManager.<init>(IFUserStoreManager.java:109)
13:09:01.365 [main] DEBUG e.s.b.g.s.GuidedGeneticAlgorithm - eu.supersede.integration.api.security.IFAuthenticationManager.<init>(IFAuthenticationManager.java:136)
13:09:01.365 [main] DEBUG e.s.b.g.s.GuidedGeneticAlgorithm - sun.reflect.GeneratedConstructorAccessor19.newInstance(Unknown Source)
13:09:01.365 [main] DEBUG e.s.b.g.s.GuidedGeneticAlgorithm - sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
13:09:01.365 [main] DEBUG e.s.b.g.s.GuidedGeneticAlgorithm - java.lang.reflect.Constructor.newInstance(Constructor.java:423)
13:09:01.365 [main] DEBUG e.s.b.g.s.GuidedGeneticAlgorithm - org.evosuite.testcase.statements.ConstructorStatement$1.execute(ConstructorStatement.java:233)
13:09:01.365 [main] DEBUG e.s.b.g.s.GuidedGeneticAlgorithm - org.evosuite.testcase.statements.AbstractStatement.exceptionHandler(AbstractStatement.java:169)
13:09:01.365 [main] DEBUG e.s.b.g.s.GuidedGeneticAlgorithm - org.evosuite.testcase.statements.ConstructorStatement.execute(ConstructorStatement.java:188)
13:09:01.365 [main] DEBUG e.s.b.g.s.GuidedGeneticAlgorithm - org.evosuite.testcase.execution.TestRunnable.executeStatements(TestRunnable.java:307)
13:09:01.365 [main] DEBUG e.s.b.g.s.GuidedGeneticAlgorithm - org.evosuite.testcase.execution.TestRunnable.call(TestRunnable.java:213)
13:09:01.365 [main] DEBUG e.s.b.g.s.GuidedGeneticAlgorithm - org.evosuite.testcase.execution.TestRunnable.call(TestRunnable.java:55)
13:09:01.365 [main] DEBUG e.s.b.g.s.GuidedGeneticAlgorithm - java.util.concurrent.FutureTask.run(FutureTask.java:266)
13:09:01.365 [main] DEBUG e.s.b.g.s.GuidedGeneticAlgorithm - java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
13:09:01.365 [main] DEBUG e.s.b.g.s.GuidedGeneticAlgorithm - java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
13:09:01.365 [main] DEBUG e.s.b.g.s.GuidedGeneticAlgorithm - java.lang.Thread.run(Thread.java:748)
13:09:01.365 [main] INFO  e.s.b.g.s.GuidedGeneticAlgorithm - Best fitness in the current population: 4.5 | 300
13:09:01.365 [main] DEBUG e.s.b.g.s.GuidedGeneticAlgorithm - Current iteration: 2
13:09:01.365 [main] DEBUG e.s.b.g.s.GuidedGeneticAlgorithm - Current value of stopping condition class org.evosuite.ga.stoppingconditions.ZeroFitnessStoppingCondition: 5
13:09:01.365 [main] DEBUG e.s.b.g.s.GuidedGeneticAlgorithm - Current value of stopping condition class org.evosuite.ga.stoppingconditions.MaxTimeStoppingCondition: 9
13:09:01.365 [main] DEBUG e.s.b.g.s.GuidedGeneticAlgorithm - Selection
13:09:01.365 [main] DEBUG e.s.b.g.s.GuidedGeneticAlgorithm - Cloning the best individuals to next generation
13:09:01.365 [main] DEBUG e.s.b.g.s.GuidedGeneticAlgorithm - Current value of stopping condition class org.evosuite.ga.stoppingconditions.ZeroFitnessStoppingCondition: 5
13:09:01.365 [main] DEBUG e.s.b.g.s.GuidedGeneticAlgorithm - Current value of stopping condition class org.evosuite.ga.stoppingconditions.MaxTimeStoppingCondition: 9
13:09:01.365 [main] DEBUG e.s.b.g.s.GuidedGeneticAlgorithm - Generating offspring
13:09:01.396 [main] DEBUG e.s.b.t.s.BotsingIndividualStrategy - Fitness calculation ... 
13:09:01.396 [main] DEBUG e.s.b.t.s.BotsingIndividualStrategy - Fitness Function: 4.5
13:09:01.417 [main] DEBUG e.s.b.t.s.BotsingIndividualStrategy - Fitness calculation ... 
13:09:01.417 [main] DEBUG e.s.b.t.s.BotsingIndividualStrategy - Fitness Function: 4.5
13:09:01.419 [main] DEBUG e.s.b.g.s.GuidedGeneticAlgorithm - Replace parents
13:09:01.419 [main] DEBUG e.s.b.g.s.GuidedGeneticAlgorithm - Current value of stopping condition class org.evosuite.ga.stoppingconditions.ZeroFitnessStoppingCondition: 5
13:09:01.419 [main] DEBUG e.s.b.g.s.GuidedGeneticAlgorithm - Current value of stopping condition class org.evosuite.ga.stoppingconditions.MaxTimeStoppingCondition: 9
13:09:01.419 [main] DEBUG e.s.b.g.s.GuidedGeneticAlgorithm - Generating offspring

Any idea on what is causing this Botsing behavior? It seems Botsing is exhausting some resources. How can I increase them?

Steps to reproduce

Botsing experiment was launched with this script:
java -jar botsing-reproduction-1.0.8.jar -Dsearch_budget=180 -Dpopulation=100 -Dtest_dir=../results/crash-reproduction-tests -crash_log ./logs/exception16b.log -target_frame 3 -project_cp ./libs -model ../results/models -Dp_object_pool=1.0 -Dsandbox=False

Other files and URLs

Relationships

Help on issue template

Preview to follow the link or open file .github/ISSUE_DOC.md

[pderakhshanfar]

Same as issue #100, this is a crash which is happened deep in the EvoSuite code. It needs some investigations.

[jesus-gorronogoitia]

We can try to debug it tomorrow in a parallel session, if you are available. Let me know.

[pderakhshanfar]

I did an investigation on this one. Apparently, EvoSuite puts a limitation on the number of iterations that we can have in the loops of software under test. Fortunately, you can modify this limitation by -Dmax_loop_iterations=<new_limitation>.

[jesus-gorronogoitia]

Thanks, I will try this out!

[jesus-gorronogoitia]

Hi @pderakhshanfar
I've run Botsing with flag: -Dmax_loop_iterations=50000

java -jar botsing-reproduction-1.0.8.jar -Dsearch_budget=180 -Dpopulation=100 -Dtest_dir=../results/crash-reproduction-tests -crash_log ./logs/exception16b.log -target_frame 3 -project_cp ./libs -model ../results/models -Dp_object_pool=1.0 -Dsandbox=False -Dmax_loop_iterations=50000

But still getting error report in logs:
08:21:31.068 [main] DEBUG e.s.b.g.s.GuidedGeneticAlgorithm - org.evosuite.runtime.TooManyResourcesException: Loop has been executed more times than the allowed 10000

Am I doing something wrong?

I see Botsing is going in the right direction to reproduce the crash, but the tentative test looks a bit repetitive:

08:21:31.068 [main] DEBUG e.s.b.g.s.GuidedGeneticAlgorithm - *  The best generated test is: IFAuthenticationManager iFAuthenticationMan
ager0 = new IFAuthenticationManager();
IFAuthenticationManager iFAuthenticationManager1 = new IFAuthenticationManager();
String string0 = "";
iFAuthenticationManager1.authenticateUser(string0, string0);
String string1 = "b]xUjz j";
String string2 = "pkiZo";
iFAuthenticationManager0.getAuthorizationToken(string1, string1, string2);
IFAuthenticationManager iFAuthenticationManager2 = new IFAuthenticationManager();
String string3 = null;
String string4 = "";
iFAuthenticationManager0.authenticateUser(string3, string4);
IFAuthenticationManager.__STATIC_RESET();
User user0 = new User();
iFAuthenticationManager2.deleteUser(user0);
User user1 = new User();
iFAuthenticationManager2.deleteUser(user1);
String string5 = "Sending message authenticateUser with userName: ";
iFAuthenticationManager1.authenticateUser(string5, string0);

because it creates two IFAuthenticationManager. Moreover, it tries to authenticateUser, what is not required before deleting an user. Maybe this is influenced by the generated behavioral model.

In any case, I can't understand the reason it exhausted the that loop, and why the input flag has no effect.
Any idea?

[pderakhshanfar]

About the generated test, the nature of Botsing (or any other genetic-based test generation approaches) is mixing different scenarios to find a test closer to the objective (here, crash reproduction). For this purpose, the algorithm may create sth repetitive or irrelevant during the search process. However, after finding a crash-reproducing test case, it cleans the achieved test case and removes the repetitive parts. So, there is no problem with repetitive or unused parts. It does not impact the eventual goal of Botsing.

[pderakhshanfar]

The loop problem is coming from a specific generated test case that iterates more than 10,000 times on a loop of your software. They put this limitation to make sure that a generated test does not get stuck in an infinite loop. So, a question that may arise here is that is it essential for your application to have a test which iterates more than 10,000 times on a loop?

If the answer is yes, according to EvoSuite's documentations, -Dmax_loop_iterations should help to increase the maximum number of loops. If it does not work, the only way that we can fix it is changing that number in a class of EvoSuite (Properties.java).

[jesus-gorronogoitia]

There's nothing in our source code that iterates if I remember well, but I will double check the methods invoked by the test generated by Botsing

[jesus-gorronogoitia]

I confirm, there are not loops in that class. There are not iterative method calls as well.
Is there any way to inform the user in logs what was the loop that exhausted the resources?

[jesus-gorronogoitia]

Hi @pderakhshanfar , IFAuthenticationManagerTest passes well, so the loop shown by Botsing when IFAuthenticationManager is accessing the external authentication service is not caused by a service unavailability.
Please, informe where I can pull EvoSuite code to change the Properties.java file, and how should I build an EvoSuite library used by Botsing.

[pderakhshanfar]

@jesus-gorronogoitia, you can set this value in Botsing source code. So, you do not need to change it in EvoSuite directly.

For now, you can add the following line to eu.stamp.botsing.Botsing.java class:

RuntimeSettings.maxNumberOfIterationsPerLoop = 50_000;

However, in the next release, I will make sure that a parameter of Botsing can set this value dynamically.