Bug 64928 - Non deterministic behaviour for Constant Throughput Timer and wrongly set value (via variable)
Summary: Non deterministic behaviour for Constant Throughput Timer and wrongly set val...
Status: NEEDINFO
Alias: None
Product: JMeter
Classification: Unclassified
Component: Main (show other bugs)
Version: 5.1.1
Hardware: PC All
: P2 normal (vote)
Target Milestone: JMETER_5.4
Assignee: JMeter issues mailing list
URL:
Keywords:
Depends on:
Blocks:
 
Reported: 2020-11-17 15:08 UTC by piotr.mirek
Modified: 2020-11-22 15:09 UTC (History)
1 user (show)



Attachments
Simple test plan with througput controller and "unknown" var (4.53 KB, application/xml)
2020-11-18 10:51 UTC, Felix Schumacher
Details
test case with the issue (8.28 KB, application/xml)
2020-11-18 11:31 UTC, piotr.mirek
Details
logs from logs viewer (3.38 KB, text/plain)
2020-11-18 11:32 UTC, piotr.mirek
Details
Add a validate function to the TestBean framework (5.62 KB, patch)
2020-11-18 13:38 UTC, Felix Schumacher
Details | Diff
Add a validate function to the TestBean framework (5.67 KB, patch)
2020-11-18 14:55 UTC, Felix Schumacher
Details | Diff

Note You need to log in before you can comment on or make changes to this bug.
Description piotr.mirek 2020-11-17 15:08:15 UTC
Component impacted:

 * Constant Throughput Timer

Case:

 * value of target throughput set to: ${__P(tpm)} (or any other variable/property)
 * tpm value is not a valid positive float number (e.g. tpm is set to 'thing' or to '-1' or even not set at all)

Currently there is no validation against given value when the test runs. No error is presented to the user and it's not easy to pinpoint the issue.

Solution:

There should be a check against the value of the variable when value of the variable/property is assigned to mentioned component, to make sure that the value is positive float number or similar.
Comment 1 Felix Schumacher 2020-11-18 10:51:02 UTC
Created attachment 37570 [details]
Simple test plan with througput controller and "unknown" var
Comment 2 Felix Schumacher 2020-11-18 10:54:53 UTC
Thanks for the report. When I configure a simple test plan (attached) with an invalid var and run the plan, I get a lot of warnings in the logs:

2020-11-18 11:48:08,076 WARN o.a.j.c.ThroughputController: Error parsing '${thing}'
java.lang.NumberFormatException: For input string: "${thing}"
	at java.lang.NumberFormatException.forInputString(NumberFormatException.java:65) ~[?:1.8.0_201]
	at java.lang.Integer.parseInt(Integer.java:569) ~[?:1.8.0_201]
	at java.lang.Integer.parseInt(Integer.java:615) ~[?:1.8.0_201]
	at org.apache.jmeter.control.ThroughputController.getMaxThroughputAsInt(ThroughputController.java:131) [ApacheJMeter_components.jar:5.3.1-SNAPSHOT]
	at org.apache.jmeter.control.ThroughputController.decide(ThroughputController.java:190) [ApacheJMeter_components.jar:5.3.1-SNAPSHOT]
	at org.apache.jmeter.control.ThroughputController.iterationStart(ThroughputController.java:229) [ApacheJMeter_components.jar:5.3.1-SNAPSHOT]
	at org.apache.jmeter.control.GenericController.fireIterationStart(GenericController.java:399) [ApacheJMeter_core.jar:5.3.1-SNAPSHOT]
	at org.apache.jmeter.control.GenericController.fireIterEvents(GenericController.java:391) [ApacheJMeter_core.jar:5.3.1-SNAPSHOT]
	at org.apache.jmeter.control.GenericController.next(GenericController.java:160) [ApacheJMeter_core.jar:5.3.1-SNAPSHOT]
	at org.apache.jmeter.control.LoopController.next(LoopController.java:134) [ApacheJMeter_core.jar:5.3.1-SNAPSHOT]
	at org.apache.jmeter.threads.AbstractThreadGroup.next(AbstractThreadGroup.java:91) [ApacheJMeter_core.jar:5.3.1-SNAPSHOT]
	at org.apache.jmeter.threads.JMeterThread.run(JMeterThread.java:254) [ApacheJMeter_core.jar:5.3.1-SNAPSHOT]
	at java.lang.Thread.run(Thread.java:748) [?:1.8.0_201]
2020-11-18 11:48:08,083 WARN o.a.j.c.ThroughputController: Error parsing '${thing}'
java.lang.NumberFormatException: For input string: "${thing}"
	at java.lang.NumberFormatException.forInputString(NumberFormatException.java:65) ~[?:1.8.0_201]
	at java.lang.Integer.parseInt(Integer.java:569) ~[?:1.8.0_201]
	at java.lang.Integer.parseInt(Integer.java:615) ~[?:1.8.0_201]
	at org.apache.jmeter.control.ThroughputController.getMaxThroughputAsInt(ThroughputController.java:131) [ApacheJMeter_components.jar:5.3.1-SNAPSHOT]
	at org.apache.jmeter.control.ThroughputController.isDone(ThroughputController.java:202) [ApacheJMeter_components.jar:5.3.1-SNAPSHOT]
	at org.apache.jmeter.control.GenericController.next(GenericController.java:162) [ApacheJMeter_core.jar:5.3.1-SNAPSHOT]
	at org.apache.jmeter.control.ThroughputController.next(ThroughputController.java:180) [ApacheJMeter_components.jar:5.3.1-SNAPSHOT]
	at org.apache.jmeter.control.GenericController.nextIsAController(GenericController.java:222) [ApacheJMeter_core.jar:5.3.1-SNAPSHOT]
	at org.apache.jmeter.control.GenericController.next(GenericController.java:175) [ApacheJMeter_core.jar:5.3.1-SNAPSHOT]
	at org.apache.jmeter.control.LoopController.next(LoopController.java:134) [ApacheJMeter_core.jar:5.3.1-SNAPSHOT]
	at org.apache.jmeter.threads.AbstractThreadGroup.next(AbstractThreadGroup.java:91) [ApacheJMeter_core.jar:5.3.1-SNAPSHOT]
	at org.apache.jmeter.threads.JMeterThread.run(JMeterThread.java:254) [ApacheJMeter_core.jar:5.3.1-SNAPSHOT]
	at java.lang.Thread.run(Thread.java:748) [?:1.8.0_201]
2020-11-18 11:48:08,084 WARN o.a.j.c.ThroughputController: Error parsing '${thing}'

Are these not enough? How could this be enhanced?

If negative numbers are given, no warning is emitted, though. I think a warning would help here, but then again, where and how should that be warned about?
Comment 3 piotr.mirek 2020-11-18 11:29:20 UTC
It's not that component.
You were testing -> logic controller -> Throughput Controller
I was referring -> timers -> Constant Throughput Timer
My bad, the title should be updated, though it was correctly stated in the descriptions.
Please see attachments with .jmx file and logs
Comment 4 piotr.mirek 2020-11-18 11:31:48 UTC
Created attachment 37571 [details]
test case with the issue

test case with the issue
Comment 5 piotr.mirek 2020-11-18 11:32:23 UTC
Created attachment 37572 [details]
logs from logs viewer
Comment 6 Felix Schumacher 2020-11-18 13:38:56 UTC
Created attachment 37573 [details]
Add a validate function to the TestBean framework

I found no other solution for the problem, other than to add a validator function passed to the TestBean framework. The problem I faced, was that I couldn't decide at neither ConstantThroughputTimer#setProperty nor #setThroughput, whether the value it got, was already completely filled in.

Maybe someone else knows a better way to add the validation logic to this class (and other classes that are using the BeanInfo construct).

Would you be able to test the patch for yourself and report back, if it would help your case?
Comment 7 Felix Schumacher 2020-11-18 14:55:35 UTC
Created attachment 37575 [details]
Add a validate function to the TestBean framework

Forgot to add the return for the valid value. Doh.
Comment 8 piotr.mirek 2020-11-20 07:52:42 UTC
I'll give it a try in the weekend. Thanks for the patch!
Comment 9 piotr.mirek 2020-11-22 15:09:24 UTC
Hi,

I've made the changes and compiled jmeter 5.2.1
There only change now is that warning is raised in logs for negative number, but no 'hard' notification is sent to the user about the problem.

Instead the warning for negative number it would be better to rise error; still problems for two other cases are not seen in the logs.

Here are the logs:

case 1 (empty value):
2020-11-22 15:55:58,072 INFO o.a.j.e.StandardJMeterEngine: Running the test!
2020-11-22 15:55:58,073 INFO o.a.j.s.SampleEvent: List of sample_variables: []
2020-11-22 15:55:58,076 INFO o.a.j.g.u.JMeterMenuBar: setRunning(true, *local*)
2020-11-22 15:55:58,226 INFO o.a.j.e.StandardJMeterEngine: Starting ThreadGroup: 1 : case1
2020-11-22 15:55:58,226 INFO o.a.j.e.StandardJMeterEngine: Starting 1 threads for group case1.
2020-11-22 15:55:58,226 INFO o.a.j.e.StandardJMeterEngine: Thread will continue on error
2020-11-22 15:55:58,227 INFO o.a.j.t.ThreadGroup: Starting thread group... number=1 threads=1 ramp-up=1 delayedStart=false
2020-11-22 15:55:58,227 INFO o.a.j.t.ThreadGroup: Started thread group number 1
2020-11-22 15:55:58,227 INFO o.a.j.e.StandardJMeterEngine: All thread groups have been started
2020-11-22 15:55:58,231 INFO o.a.j.t.JMeterThread: Thread started: case1 1-1

case 2 (negative number):
2020-11-22 15:57:54,074 INFO o.a.j.e.StandardJMeterEngine: Running the test!
2020-11-22 15:57:54,074 INFO o.a.j.s.SampleEvent: List of sample_variables: []
2020-11-22 15:57:54,075 WARN o.a.j.t.ConstantThroughputTimerBeanInfo: Number must not be less than zero: [-1.0]
2020-11-22 15:57:54,075 WARN o.a.j.t.TestBeanHelper: Invalid value [-1.0] for property [throughput]
2020-11-22 15:57:54,075 INFO o.a.j.g.u.JMeterMenuBar: setRunning(true, *local*)
2020-11-22 15:57:54,227 INFO o.a.j.e.StandardJMeterEngine: Starting ThreadGroup: 1 : case2
2020-11-22 15:57:54,227 INFO o.a.j.e.StandardJMeterEngine: Starting 1 threads for group case2.
2020-11-22 15:57:54,227 INFO o.a.j.e.StandardJMeterEngine: Thread will continue on error
2020-11-22 15:57:54,227 INFO o.a.j.t.ThreadGroup: Starting thread group... number=1 threads=1 ramp-up=1 delayedStart=false
2020-11-22 15:57:54,228 INFO o.a.j.t.ThreadGroup: Started thread group number 1
2020-11-22 15:57:54,228 INFO o.a.j.e.StandardJMeterEngine: All thread groups have been started
2020-11-22 15:57:54,229 INFO o.a.j.t.JMeterThread: Thread started: case2 1-1
2020-11-22 15:57:54,230 WARN o.a.j.t.ConstantThroughputTimerBeanInfo: Number must not be less than zero: [-1.0]
2020-11-22 15:57:54,231 WARN o.a.j.t.TestBeanHelper: Invalid value [-1.0] for property [throughput]
2020-11-22 15:57:54,231 INFO o.a.j.t.JMeterThread: Thread is done: case2 1-1
2020-11-22 15:57:54,232 INFO o.a.j.t.JMeterThread: Thread finished: case2 1-1
2020-11-22 15:57:54,232 INFO o.a.j.e.StandardJMeterEngine: Notifying test listeners of end of test
2020-11-22 15:57:54,232 INFO o.a.j.g.u.JMeterMenuBar: setRunning(false, *local*)


case 3 (string value):
2020-11-22 15:58:42,568 INFO o.a.j.e.StandardJMeterEngine: Running the test!
2020-11-22 15:58:42,568 INFO o.a.j.s.SampleEvent: List of sample_variables: []
2020-11-22 15:58:42,571 INFO o.a.j.g.u.JMeterMenuBar: setRunning(true, *local*)
2020-11-22 15:58:42,708 INFO o.a.j.e.StandardJMeterEngine: Starting ThreadGroup: 1 : case3
2020-11-22 15:58:42,709 INFO o.a.j.e.StandardJMeterEngine: Starting 1 threads for group case3.
2020-11-22 15:58:42,709 INFO o.a.j.e.StandardJMeterEngine: Thread will continue on error
2020-11-22 15:58:42,709 INFO o.a.j.t.ThreadGroup: Starting thread group... number=1 threads=1 ramp-up=1 delayedStart=false
2020-11-22 15:58:42,709 INFO o.a.j.t.ThreadGroup: Started thread group number 1
2020-11-22 15:58:42,709 INFO o.a.j.e.StandardJMeterEngine: All thread groups have been started
2020-11-22 15:58:42,710 INFO o.a.j.t.JMeterThread: Thread started: case3 1-1