-
Notifications
You must be signed in to change notification settings - Fork 112
New issue
Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.
By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.
Already on GitHub? Sign in to your account
Distributed tests only run once #67
Comments
First I think we need to rule out if the controlling master instance is not starting the second test on the minion servers. If it is indeed starting the second test on the minion servers, then we should see some errors about the http server not starting up? You can increase the log of this library by adding this Logger to your log4j2.xml of the minion servers |
just a minor typo it should be But yes, after adding the extra logging i can see the below line logged only once in every minion. but that line occurs everytime in the master |
this is the entire log for a minion. I have blurred any ip address, tho 2019-10-16 21:01:25,706 INFO o.a.j.u.JMeterUtils: Setting Locale to en_EN 2019-10-16 21:01:25,719 INFO o.a.j.JMeter: Loading user properties from: /opt/ggs/config/ggs.properties 2019-10-16 21:01:25,719 INFO o.a.j.JMeter: Loading system properties from: /opt/jmeter/bin/system.properties 2019-10-16 21:01:25,720 INFO o.a.j.JMeter: Setting System property: server_port=1099 2019-10-16 21:01:25,720 INFO o.a.j.JMeter: Setting System property: server.rmi.localport=60001 2019-10-16 21:01:25,720 INFO o.a.j.JMeter: Setting System property: server_port=1099 2019-10-16 21:01:25,720 INFO o.a.j.JMeter: Setting JMeter property: server.rmi.ssl.disable=true 2019-10-16 21:01:25,720 INFO o.a.j.JMeter: LogLevel: com.github.johrstrom=DEBUG 2019-10-16 21:01:25,725 INFO o.a.j.JMeter: Copyright (c) 1998-2019 The Apache Software Foundation 2019-10-16 21:01:25,725 INFO o.a.j.JMeter: Version 5.1 r1853635 2019-10-16 21:01:25,725 INFO o.a.j.JMeter: java.version=1.8.0_222 2019-10-16 21:01:25,725 INFO o.a.j.JMeter: java.vm.name=OpenJDK 64-Bit Server VM 2019-10-16 21:01:25,726 INFO o.a.j.JMeter: os.name=Linux 2019-10-16 21:01:25,726 INFO o.a.j.JMeter: os.arch=amd64 2019-10-16 21:01:25,726 INFO o.a.j.JMeter: os.version=4.14.146-119.123.amzn2.x86_64 2019-10-16 21:01:25,726 INFO o.a.j.JMeter: file.encoding=UTF-8 2019-10-16 21:01:25,726 INFO o.a.j.JMeter: java.awt.headless=true 2019-10-16 21:01:25,726 INFO o.a.j.JMeter: Max memory =1073741824 2019-10-16 21:01:25,726 INFO o.a.j.JMeter: Available Processors =8 2019-10-16 21:01:25,740 INFO o.a.j.JMeter: Default Locale=English (EN) 2019-10-16 21:01:25,741 INFO o.a.j.JMeter: JMeter Locale=English (EN) 2019-10-16 21:01:25,741 INFO o.a.j.JMeter: JMeterHome=/opt/jmeter 2019-10-16 21:01:25,741 INFO o.a.j.JMeter: user.dir =/ 2019-10-16 21:01:25,741 INFO o.a.j.JMeter: PWD =/ 2019-10-16 21:01:25,741 INFO o.a.j.JMeter: IP: some.ip.address Name: FullName: 2019-10-16 21:01:25,748 INFO o.a.j.r.RmiUtils: Disabling SSL for RMI as server.rmi.ssl.disable is set to 'true' 2019-10-16 21:01:25,748 INFO o.a.j.r.RmiUtils: Disabling SSL for RMI as server.rmi.ssl.disable is set to 'true' 2019-10-16 21:01:25,767 INFO o.a.j.e.RemoteJMeterEngineImpl: Starting backing engine on 1099 2019-10-16 21:01:25,767 INFO o.a.j.r.RmiUtils: System property 'java.rmi.server.hostname' is not defined, using localHost address 2019-10-16 21:01:25,767 INFO o.a.j.r.RmiUtils: Local IP address=some.ip.address 2019-10-16 21:01:25,768 INFO o.a.j.e.RemoteJMeterEngineImpl: IP address is a site-local address; this may cause problems with remote access. Can be overridden by defining the system property 'java.rmi.server.hostname' - see jmeter-server script file 2019-10-16 21:01:25,768 INFO o.a.j.e.RemoteJMeterEngineImpl: Creating RMI registry (server.rmi.create=true) 2019-10-16 21:01:25,768 INFO o.a.j.r.RmiUtils: Disabling SSL for RMI as server.rmi.ssl.disable is set to 'true' 2019-10-16 21:01:25,768 INFO o.a.j.r.RmiUtils: Disabling SSL for RMI as server.rmi.ssl.disable is set to 'true' 2019-10-16 21:01:25,770 INFO o.a.j.e.RemoteJMeterEngineImpl: Bound to RMI registry on port 1099 2019-10-16 21:04:29,099 INFO o.a.j.s.SampleEvent: List of sample_variables: [] 2019-10-16 21:04:29,104 INFO o.a.j.s.BatchSampleSender: Using batching for this run. Thresholds: num=100, time=60000 2019-10-16 21:04:29,105 INFO o.a.j.s.DataStrippingSampleSender: Using DataStrippingSampleSender for this run with stripAlsoOnError: true 2019-10-16 21:04:29,106 INFO o.a.j.s.BatchSampleSender: Using batching for this run. Thresholds: num=100, time=60000 2019-10-16 21:04:29,106 INFO o.a.j.s.DataStrippingSampleSender: Using DataStrippingSampleSender for this run with stripAlsoOnError: true 2019-10-16 21:04:29,106 INFO o.a.j.s.BatchSampleSender: Using batching for this run. Thresholds: num=100, time=60000 2019-10-16 21:04:29,106 INFO o.a.j.s.DataStrippingSampleSender: Using DataStrippingSampleSender for this run with stripAlsoOnError: true 2019-10-16 21:04:29,138 INFO o.a.j.p.h.s.HTTPSamplerBase: Parser for text/html is org.apache.jmeter.protocol.http.parser.LagartoBasedHtmlParser 2019-10-16 21:04:29,138 INFO o.a.j.p.h.s.HTTPSamplerBase: Parser for application/xhtml+xml is org.apache.jmeter.protocol.http.parser.LagartoBasedHtmlParser 2019-10-16 21:04:29,138 INFO o.a.j.p.h.s.HTTPSamplerBase: Parser for application/xml is org.apache.jmeter.protocol.http.parser.LagartoBasedHtmlParser 2019-10-16 21:04:29,138 INFO o.a.j.p.h.s.HTTPSamplerBase: Parser for text/xml is org.apache.jmeter.protocol.http.parser.LagartoBasedHtmlParser 2019-10-16 21:04:29,138 INFO o.a.j.p.h.s.HTTPSamplerBase: Parser for text/vnd.wap.wml is org.apache.jmeter.protocol.http.parser.RegexpHTMLParser 2019-10-16 21:04:29,138 INFO o.a.j.p.h.s.HTTPSamplerBase: Parser for text/css is org.apache.jmeter.protocol.http.parser.CssParser 2019-10-16 21:04:29,163 INFO o.a.j.s.BatchSampleSender: Using batching for this run. Thresholds: num=100, time=60000 2019-10-16 21:04:29,163 INFO o.a.j.s.DataStrippingSampleSender: Using DataStrippingSampleSender for this run with stripAlsoOnError: true 2019-10-16 21:04:29,163 INFO o.a.j.s.BatchSampleSender: Using batching for this run. Thresholds: num=100, time=60000 2019-10-16 21:04:29,163 INFO o.a.j.s.DataStrippingSampleSender: Using DataStrippingSampleSender for this run with stripAlsoOnError: true 2019-10-16 21:04:29,173 INFO o.a.j.e.RemoteJMeterEngineImpl: Creating JMeter engine on host some.ip.address base 'opt/ggs' 2019-10-16 21:04:29,174 INFO o.a.j.e.RemoteJMeterEngineImpl: Remote client host: some.client.ip.address 2019-10-16 21:04:29,176 INFO o.a.j.s.FileServer: Default base='/' 2019-10-16 21:04:29,181 INFO o.a.j.s.FileServer: Set new base='opt/ggs' 2019-10-16 21:04:29,182 INFO o.a.j.e.StandardJMeterEngine: Applying properties {} 2019-10-16 21:04:29,182 INFO o.a.j.e.RemoteJMeterEngineImpl: Running test 2019-10-16 21:04:29,185 INFO o.a.j.e.StandardJMeterEngine: Running the test! 2019-10-16 21:04:29,185 INFO o.a.j.s.SampleEvent: List of sample_variables: [] 2019-10-16 21:04:29,192 INFO o.a.j.e.u.CompoundVariable: Note: Function class names must contain the string: '.functions.' 2019-10-16 21:04:29,192 INFO o.a.j.e.u.CompoundVariable: Note: Function class names must not contain the string: '.gui.' 2019-10-16 21:04:29,471 INFO k.a.j.t.UltimateThreadGroup: GUI threads profile will be ignored 2019-10-16 21:04:29,492 INFO k.a.j.t.UltimateThreadGroup: Setting threads profile from property threads_schedule: spawn(4,0s,30s,100s,30s) 2019-10-16 21:04:29,493 WARN c.g.j.l.PrometheusListener: Collector registry has not yet been initialized, doing it now 2019-10-16 21:04:29,494 DEBUG c.g.j.c.JMeterCollectorRegistry: Creating prometheus collector registry 2019-10-16 21:04:29,505 DEBUG c.g.j.l.PrometheusListener: Creating collector from configuration: [collector.help: default help string, collector.metric_name: jmeter_samples_latency, collector.type: SUMMARY, collector.labels: [label, code], collector.quantiles_or_buckets: 0.75,0.5|0.95,0.1|0.99,0.01, listener.collector.measuring: Latency, ] 2019-10-16 21:04:29,506 DEBUG c.g.j.c.JMeterCollectorRegistry: created and registered [collector.help: default help string, collector.metric_name: jmeter_samples_latency, collector.type: SUMMARY, collector.labels: [label, code], collector.quantiles_or_buckets: 0.75,0.5|0.95,0.1|0.99,0.01, listener.collector.measuring: Latency, ] 2019-10-16 21:04:29,507 DEBUG c.g.j.l.PrometheusListener: added jmeter_samples_latency to list of collectors 2019-10-16 21:04:29,507 DEBUG c.g.j.l.PrometheusListener: Creating collector from configuration: [collector.help: default help string, collector.metric_name: jmeter_samples_response_time, collector.type: SUMMARY, collector.labels: [label, code], collector.quantiles_or_buckets: 0.75,0.5|0.95,0.1|0.99,0.01, listener.collector.measuring: ResponseTime, ] 2019-10-16 21:04:29,507 DEBUG c.g.j.c.JMeterCollectorRegistry: created and registered [collector.help: default help string, collector.metric_name: jmeter_samples_response_time, collector.type: SUMMARY, collector.labels: [label, code], collector.quantiles_or_buckets: 0.75,0.5|0.95,0.1|0.99,0.01, listener.collector.measuring: ResponseTime, ] 2019-10-16 21:04:29,508 DEBUG c.g.j.l.PrometheusListener: added jmeter_samples_response_time to list of collectors 2019-10-16 21:04:29,508 DEBUG c.g.j.l.PrometheusListener: Creating collector from configuration: [collector.help: default help string, collector.metric_name: jmeter_samples_success_ratio, collector.type: SUCCESS_RATIO, collector.labels: [], collector.quantiles_or_buckets: , listener.collector.measuring: SuccessRatio, ] 2019-10-16 21:04:29,508 DEBUG c.g.j.c.JMeterCollectorRegistry: created and registered [collector.help: default help string, collector.metric_name: jmeter_samples_success_ratio, collector.type: SUCCESS_RATIO, collector.labels: [], collector.quantiles_or_buckets: , listener.collector.measuring: SuccessRatio, ] 2019-10-16 21:04:29,509 DEBUG c.g.j.l.PrometheusListener: added jmeter_samples_success_ratio to list of collectors 2019-10-16 21:04:29,509 WARN c.g.j.l.PrometheusListener: Prometheus server has not yet been initialized, doing it now 2019-10-16 21:04:29,510 DEBUG c.g.j.l.PrometheusServer: Creating Prometheus Server 2019-10-16 21:04:29,554 INFO o.a.j.e.StandardJMeterEngine: Starting ThreadGroup: 1 : Thread Group 2019-10-16 21:04:29,555 INFO k.a.j.t.UltimateThreadGroup: GUI threads profile will be ignored 2019-10-16 21:04:29,555 INFO k.a.j.t.UltimateThreadGroup: Setting threads profile from property threads_schedule: spawn(4,0s,30s,100s,30s) 2019-10-16 21:04:29,555 INFO o.a.j.e.StandardJMeterEngine: Starting 4 threads for group Thread Group. 2019-10-16 21:04:29,555 INFO o.a.j.e.StandardJMeterEngine: Thread will continue on error 2019-10-16 21:04:29,555 INFO k.a.j.t.UltimateThreadGroup: GUI threads profile will be ignored 2019-10-16 21:04:29,555 INFO k.a.j.t.UltimateThreadGroup: Setting threads profile from property threads_schedule: spawn(4,0s,30s,100s,30s) 2019-10-16 21:04:29,556 INFO k.a.j.t.AbstractSimpleThreadGroup: Starting thread group number 1 threads 4 2019-10-16 21:04:29,562 INFO k.a.j.t.AbstractSimpleThreadGroup: Started thread group number 1 2019-10-16 21:04:29,562 INFO o.a.j.e.StandardJMeterEngine: All thread groups have been started 2019-10-16 21:04:37,056 INFO o.a.j.t.JMeterThread: Thread started: some.ip.address-Thread Group 1-4 2019-10-16 21:04:37,058 INFO o.a.j.s.FileServer: Stored: /opt/ggs/addresses.csv Alias: /opt/ggs/addresses.csv@"All threads" 2019-10-16 21:04:37,081 INFO o.a.j.p.h.s.HTTPHCAbstractImpl: Local host = jmeter-slaves-68d96c868b-dpw6l 2019-10-16 21:04:37,086 INFO o.a.j.p.h.s.HTTPHC4Impl: HTTP request retry count = 0 2019-10-16 21:04:37,088 INFO o.a.j.s.SampleResult: Note: Sample TimeStamps are START times 2019-10-16 21:04:37,088 INFO o.a.j.s.SampleResult: sampleresult.default.encoding is set to ISO-8859-1 2019-10-16 21:04:37,088 INFO o.a.j.s.SampleResult: sampleresult.useNanoTime=true 2019-10-16 21:04:37,088 INFO o.a.j.s.SampleResult: sampleresult.nanoThreadSleep=5000 2019-10-16 21:04:44,557 INFO o.a.j.t.JMeterThread: Thread started: some.ip.address-Thread Group 1-3 2019-10-16 21:04:46,476 INFO o.a.j.u.JsseSSLManager: Using default SSL protocol: TLS 2019-10-16 21:04:46,476 INFO o.a.j.u.JsseSSLManager: SSL session context: per-thread 2019-10-16 21:04:52,056 INFO o.a.j.t.JMeterThread: Thread started: some.ip.address-Thread Group 1-2 2019-10-16 21:04:59,556 INFO o.a.j.t.JMeterThread: Thread started: some.ip.address-Thread Group 1-1 2019-10-16 21:06:47,905 INFO o.a.j.t.JMeterThread: Stopping because end time detected by thread: some.ip.address-Thread Group 1-4 2019-10-16 21:06:47,905 INFO o.a.j.t.JMeterThread: Thread finished: some.ip.address-Thread Group 1-4 2019-10-16 21:06:55,335 INFO o.a.j.t.JMeterThread: Stopping because end time detected by thread: some.ip.address-Thread Group 1-3 2019-10-16 21:06:55,335 INFO o.a.j.t.JMeterThread: Thread finished: some.ip.address-Thread Group 1-3 2019-10-16 21:07:02,086 INFO o.a.j.t.JMeterThread: Stopping because end time detected by thread: some.ip.address-Thread Group 1-2 2019-10-16 21:07:02,086 INFO o.a.j.t.JMeterThread: Thread finished: some.ip.address-Thread Group 1-2 2019-10-16 21:07:09,591 INFO o.a.j.t.JMeterThread: Stopping because end time detected by thread: some.ip.address-Thread Group 1-1 2019-10-16 21:07:09,591 INFO o.a.j.t.JMeterThread: Thread finished: some.ip.address-Thread Group 1-1 2019-10-16 21:07:09,592 INFO o.a.j.e.StandardJMeterEngine: Notifying test listeners of end of test 2019-10-16 21:07:09,592 INFO o.a.j.s.FileServer: Close: /opt/ggs/addresses.csv@"All threads" 2019-10-16 21:07:09,592 INFO o.a.j.s.DataStrippingSampleSender: Test Ended on some.ip.address 2019-10-16 21:07:09,592 INFO o.a.j.s.BatchSampleSender: Test Ended on some.ip.address 2019-10-16 21:07:09,594 INFO o.a.j.s.DataStrippingSampleSender: Test Ended on some.ip.address 2019-10-16 21:07:09,594 INFO o.a.j.s.BatchSampleSender: Test Ended on some.ip.address 2019-10-16 21:07:09,595 INFO o.a.j.s.DataStrippingSampleSender: Test Ended on some.ip.address 2019-10-16 21:07:09,595 INFO o.a.j.s.BatchSampleSender: Test Ended on some.ip.address 2019-10-16 21:07:09,596 INFO o.a.j.s.DataStrippingSampleSender: Test Ended on some.ip.address 2019-10-16 21:07:09,596 INFO o.a.j.s.BatchSampleSender: Test Ended on some.ip.address 2019-10-16 21:07:09,597 DEBUG c.g.j.c.JMeterCollectorRegistry: unregistering jmeter_samples_latency 2019-10-16 21:07:09,597 DEBUG c.g.j.c.JMeterCollectorRegistry: unregistering jmeter_samples_success_ratio 2019-10-16 21:07:09,598 DEBUG c.g.j.c.JMeterCollectorRegistry: unregistering jmeter_samples_response_time 2019-10-16 21:07:09,598 INFO o.a.j.s.DataStrippingSampleSender: Test Ended on some.ip.address 2019-10-16 21:07:09,598 INFO o.a.j.s.BatchSampleSender: Test Ended on some.ip.address 2019-10-16 21:07:09,601 INFO o.a.j.e.StandardJMeterEngine: Test has ended on host some.ip.address |
So after a little digging, and git cloning your repo, i noticed that the problem is due to shutting down the service executor. you can reproduce the error, in your unit test. if you update the test to this public class PrometheusServerTest {
@Test
public void ensureCleanStartStop() throws Exception {
PrometheusServer server = PrometheusServer.getInstance();
Assert.assertNotNull(server);
server.start();
Thread.currentThread();
Thread.sleep(1000);
String data = getScrapes();
server.stop();
server.start();
Thread.currentThread();
Thread.sleep(1000);
String data2 = getScrapes();
server.stop();
}
private String getScrapes() throws IOException {
URL url = new URL("http://localhost:9270/metrics");
URLConnection conn = url.openConnection();
conn.setReadTimeout(3000);
BufferedReader in = new BufferedReader(new InputStreamReader(conn.getInputStream()));
StringBuilder sb = new StringBuilder();
String line = "";
while ((line = in.readLine()) != null) {
sb.append(line);
}
return sb.toString();
}
} so for the test to pass you have 2 options: |
Thanks for all the info. I started to look into this, then got into a rabbit hole trying to containerize my jmeter setup. I'll try to get around to this this weekend. |
For what's worth, you can get the same behaviour when you load your example in JMeter and start / stop the test. The first time the server starts correctly and Prometheus can scrape it. Consecutive times the server returns an empty response. |
Thanks all for contributing to this. GH closed this based off of my commit message, but I've released version 0.5.2 which I believe resolves this. I'll keep this open for just a little bit to get some confirmation. Let me know if it doesn't fix it (or even if it does let me know). Thanks again! |
Works fine in JMeter GUI mode 😄 Thanks for the quick fix, helps during test case development! |
I'm going to close this now. Let me know if it comes back! thanks again all. |
Able to replicate against 0.6.0 version |
Hi, I got same issue by using 0.6.0 version jar. Running distributed mode using docker, got master and N slaves running on same server, local host:9270 is not reachable. Did you manage to get the solution for this? Please advice me Thanks |
@joris-lambrechts i am seeing same issue for distribution testing. can you help me on this, master and slaves are running as docker containers. |
Originally posted in #62. I'm moving it here because it seems to be a whole new thing and possibly a bug in this library. Originally opened there by @jrodguitar.
The text was updated successfully, but these errors were encountered: