Bug 51868 - A lot of exceptions in jmeter.log while using option "Start next loop" for thread
A lot of exceptions in jmeter.log while using option "Start next loop" for th...
Status: RESOLVED FIXED
Product: JMeter
Classification: Unclassified
Component: Main
2.5.1
All All
: P2 critical (vote)
: ---
Assigned To: JMeter issues mailing list
:
Depends on:
Blocks: 51866
  Show dependency tree
 
Reported: 2011-09-22 08:39 UTC by Oleg
Modified: 2012-01-15 13:40 UTC (History)
1 user (show)



Attachments
Scenario for reproducing error (16.42 KB, application/octet-stream)
2011-09-22 08:39 UTC, Oleg
Details
Example of jmeter.log (124.64 KB, application/octet-stream)
2011-09-22 08:40 UTC, Oleg
Details
Variables (201.43 KB, image/jpeg)
2011-09-22 11:04 UTC, Oleg
Details
Debug log (5.42 KB, application/octet-stream)
2011-09-22 11:04 UTC, Oleg
Details
Fix to bad handling of error in Condition (691 bytes, patch)
2011-10-01 16:05 UTC, Philippe Mouawad
Details | Diff
FIx to issue (5.16 KB, patch)
2011-10-02 06:48 UTC, Philippe Mouawad
Details | Diff
Fix to issue taking into account your note in issue 51866 (6.12 KB, patch)
2011-10-05 13:32 UTC, Philippe Mouawad
Details | Diff

Note You need to log in before you can comment on or make changes to this bug.
Description Oleg 2011-09-22 08:39:39 UTC
Created attachment 27558 [details]
Scenario for reproducing error

In some cases thread writes to log multiple exceptions (about 10MB per second).
Error occured in some combinations of controllers (presense/absence of "Once Only" and "If" controllers, beanshell samplers etc
Simple scenario for reproducing have such structure:
TestPlan
+ThreadGroup (Start next loop on error)
+BeanShellSampler (Some preparations)
++Loop(Forever)
+++HTTPRequests
+++BeanShellSampler(Using data from preparations)
+++IfController(condition based on beanshell result)
++++SomeActions
If no any errors in samplers, scanario executed properly.
If error occured, then huge exceptions in log, no any further samplers execution, thread remain active
If any of following conditions become true, no such count of exceptions in log writed:
1) "If contorller" named "Validation based of beanshell values" disabled
2) loop has definite count of loops (not "forever")
3) absense of "BeanShell" samplers

I prepared scenario for reproducing.
First, run it as is, then see log (all sampler must be successfull).
Then, enable step "(fail) Load page (loop)" and run again. See log - GBs of exceptions
P.S. this example is one of many cases for repeating this error. Mostly simplified
Comment 1 Oleg 2011-09-22 08:40:30 UTC
Created attachment 27559 [details]
Example of jmeter.log

jmeter.log attached
Comment 2 Sebb 2011-09-22 09:18:41 UTC
2011/09/22 12:36:56 ERROR - jmeter.control.IfController: missing ; before statement (<cmd>#1) org.mozilla.javascript.EvaluatorException: missing ; before statement (<cmd>#1)

is caused by a syntax error in the JMX file

Try disabling them in turn until the problem disappears, and then double-check the variables don't contain spaces etc. - use the Debug sampler.
Comment 3 Oleg 2011-09-22 09:41:30 UTC
Please look at attachment. Error occured ONLY if option "Start next loop on error" set. Before error in sample all actions were successfull and all samplers after failed sampler must not be executed. But if ni any errors in loop occured, all work properly
Comment 4 Sebb 2011-09-22 10:25:19 UTC
Have you tried using the Debug Sampler to see what the variables are?

Have you tried finding out which If Controller is involved?

Have you tried enabling debug logging for the If Controller?

This will help narrow down the issue.
Comment 5 Oleg 2011-09-22 11:03:17 UTC
(In reply to comment #4)
> Have you tried using the Debug Sampler to see what the variables are?
  Yes. If no any errors in sample, variables calculated in BeanShell and used in IFC are valid  (see screenshot)

> Have you tried finding out which If Controller is involved?
  There is the only IFC in scenario. It work properly, if errors absent. And it must not be validated, if error occured at any sampler before IFC

> Have you tried enabling debug logging for the If Controller?
  In jmeter.properties I set everything to DEBUG. Now I see 2 errors here - one about recirculation (51865) and another - exception. IFC try to validate undefined value (getCondition() : [${spent_time}>5000]). Yes, it is not valid. But IFC must not be processed at all, because value calculating for IFC and IFC are at the end of loop. After error first sample of loop must be processed, is it?
Log attached
 
> This will help narrow down the issue.
Comment 6 Oleg 2011-09-22 11:04:02 UTC
Created attachment 27560 [details]
Variables
Comment 7 Oleg 2011-09-22 11:04:43 UTC
Created attachment 27561 [details]
Debug log
Comment 8 Philippe Mouawad 2011-10-01 15:27:51 UTC
Hello,
Your second BeanShell Sampler has an error, it should be:
vars.put("spent_time",execution_time.toString());

look in jmeter.log you have:
2011/10/01 17:05:14 ERROR - jmeter.util.BeanShellInterpreter: Error invoking bsh method: eval	Sourced file: inline evaluation of: ``current_time = System.currentTimeMillis(); start_time = vars.get("start_time");  . . . '' : Error in method invocation: Method put( java.lang.String, long ) not found in class'org.apache.jmeter.threads.JMeterVariables' 
2011/10/01 17:05:16 WARN  - jmeter.protocol.java.sampler.BeanShellSampler: org.apache.jorphan.util.JMeterException: Error invoking bsh method: eval	Sourced file: inline evaluation of: ``current_time = System.currentTimeMillis(); start_time = vars.get("start_time");  . . . '' : Error in method invocation: Method put( java.lang.String, long ) not found in class'org.apache.jmeter.threads.JMeterVariables' 


Regarding the issue, this is my analysis, 
when error occurs in either HTTP Sampler or bean, as Start NExt loop is configured we enter this part of code of JMeterThread:

sam = controller.next(); // need perfom a until loop for special case (tc as parent)

while (sam != null && !sam.equals(firstSampler)) { // while the thread is NOT on the begining of the tree
    sam = controller.next();
}

next controller is IfController , I think we enter a known issue:
"The If Controller may cause an infinite loop if the condition is always false from the first iteration"


Anyway, Maybe IfController#evaluateCondition should throw an exception when condition has a evaluation error instead of returning false, it would stop test and let you know your condition is wrong.
Regards
Philippe
Comment 9 Philippe Mouawad 2011-10-01 16:05:31 UTC
Created attachment 27658 [details]
Fix to bad handling of error in Condition
Comment 10 Philippe Mouawad 2011-10-01 16:23:56 UTC
Sorry I think I read too fast
Part of my analysis is wrong.
I recap:
When an error occurs (enabled (fail) Load page (loop)) JMeterThread will enter this part of code:
sam = controller.next(); // need perfom a until loop for special case (tc as
parent)

while (sam != null && !sam.equals(firstSampler)) { // while the thread is NOT
on the begining of the tree
    sam = controller.next();
}

It means if will for IfController execute the condition which is wrong due to the fact that BeanShell sampler just before did not run, so spend_time won't be in variables.

That explains the logs.
Regards
Philippe
Comment 11 Philippe Mouawad 2011-10-01 16:58:11 UTC
A fix to issue would be to flag we are in a restartNextLoop
try{
                                JMeterContextService.getContext().setIsWithinRestartNextLoop();
                                // Last not ok. start get the begining of the tree
                                sam = controller.next(); // need perfom a until loop for special case (tc as parent)
                                while (sam != null && !sam.equals(firstSampler)) { // while the thread is NOT on the begining of the tree
                                    sam = controller.next();
                                }
                                // At this point: begining tree, thus Last must Ok
                                threadContext.getVariables().put(LAST_SAMPLE_OK, TRUE);
                            } finally {
                                JMeterContextService.getContext().unsetIsWithinRestartNextLoop();                                
                            }

In IfController#next:
Test for flag and don't eval condition but what to return ?


What's your opinion ssebb ?

Regards
Philippe
Comment 12 Philippe Mouawad 2011-10-02 06:48:50 UTC
Created attachment 27669 [details]
FIx to issue

Hello,
I implemented described solution that sets a flag when within restart next loop code in JMeterThread.
IfController tests this state and does not evaluate condition and return next sampler as if condition was true.

Regards
Philippe
Comment 13 Philippe Mouawad 2011-10-05 13:32:49 UTC
Created attachment 27696 [details]
Fix to issue taking into account your note in issue 51866

Hello,
I think this fixes both 51868 and 51866.

ant test passed OK 
2 Test plans of 51866 and Test plan of 51868 also passed OK.
Regards
Philippe M.
Comment 14 Philippe Mouawad 2011-10-31 10:52:16 UTC
Date: Mon Oct 31 10:50:11 2011
New Revision: 1195404

URL: http://svn.apache.org/viewvc?rev=1195404&view=rev
Log:
Fix to Start Next Loop broken feature, fixes following issues:
- Bug 51865 - Infinite loop inside thread group does not work properly if "Start next loop after a Sample error" option set
- Bug 51868 - A lot of exceptions in jmeter.log while using option "Start next loop" for thread
- Bug 51866 - Counter under loop doesn't work properly if "Start next loop on error" option set for thread group


Added:
   jakarta/jmeter/trunk/src/core/org/apache/jmeter/threads/FindTestElementsUpToRootTraverser.java   (with props)
Modified:
   jakarta/jmeter/trunk/src/components/org/apache/jmeter/control/ForeachController.java
   jakarta/jmeter/trunk/src/core/org/apache/jmeter/control/Controller.java
   jakarta/jmeter/trunk/src/core/org/apache/jmeter/control/GenericController.java
   jakarta/jmeter/trunk/src/core/org/apache/jmeter/control/IfController.java
   jakarta/jmeter/trunk/src/core/org/apache/jmeter/control/LoopController.java
   jakarta/jmeter/trunk/src/core/org/apache/jmeter/control/RunTime.java
   jakarta/jmeter/trunk/src/core/org/apache/jmeter/control/WhileController.java
   jakarta/jmeter/trunk/src/core/org/apache/jmeter/threads/AbstractThreadGroup.java
   jakarta/jmeter/trunk/src/core/org/apache/jmeter/threads/JMeterThread.java
   jakarta/jmeter/trunk/xdocs/changes.xml
Comment 15 Philippe Mouawad 2011-11-01 10:04:53 UTC
Hello,
A Fix has been provided, it would be Nice of you to test it and submit a comment confirming it is fixed for you.

Regards
Comment 16 Oleg 2011-12-13 14:07:38 UTC
verified on r1213077
Comment 17 Philippe Mouawad 2012-01-15 13:40:08 UTC
I change state cause with VERIFIED state , issue still appears as opened in weekly bug report.
Thanks for verification.