I have been investigating an issue where, when running tests for long
periods of time (between 4 and 12 hours), some http requests (normally
0.5% or less of the total) fail with this exception
java.io.IOException: Stream closed
at java.io.BufferedInputStream.getInIfOpen(BufferedInputStream.java:134)
at java.io.BufferedInputStream.read1(BufferedInputStream.java:254)
at java.io.BufferedInputStream.read(BufferedInputStream.java:313)
at java.io.FilterInputStream.read(FilterInputStream.java:90)
at
org.apache.jmeter.protocol.http.sampler.HTTPSampler.readResponse(HTTPSampler.java:235)
at
org.apache.jmeter.protocol.http.sampler.HTTPSampler.sample(HTTPSampler.java:449)
at
org.apache.jmeter.protocol.http.sampler.HTTPSamplerBase.sample(HTTPSamplerBase.java:514)
at
org.apache.jmeter.protocol.http.sampler.HTTPSamplerBase.sample(HTTPSamplerBase.java:503)
at org.apache.jmeter.threads.JMeterThread.run(JMeterThread.java:247)
at java.lang.Thread.run(Thread.java:595)
To trace better the failing requests, I added a counter and a timestamp
parameter to each http request
The values for the parameters are defined in the HTTP request defaults
for the thread group as
${__counter(false, count)}
${__javaScript(new Date().getTime(),timestamp)}
and are ignored, but logged, by the Tomcat servlet that I am testing
In the application logs, I would therefore expect to see only unique
requests, but I have seen that when a request fails in JMeter with the
"Stream closed" exception, is present twice in the application logs.
In both instances, the application logs indicate that the request has
been correctly processed (although the first one took over 5 minutes)
To understand whether the problem was on the load balancer/application
side or JMeter, I ran this tcpdump command on the client side while
running the test:
tcpdump -w jmeter-tcpdump-log -C 2 -Aq -s 1520 dst host tc-chromium
so I would record all the requests sent from the test computer to the
application.
If I reopen the log with tcpdump -r, I see the request twice, with a
delta of almost exactly 5 minutes.
22:40:43.720789 IP iridium.sharpmind.de.60899 >
tc-chromium-ext.sharpmind.de.http-alt: P 0:406(406) ack 1 win 1460
[EMAIL PROTECTED]@..V
..j
..
......He....P....N..GET
/?gps_history=1337300;5251640;20;30;$&way_points=1342157;5238465;$&destination=784964;4799853;&cmd=navigate&version=1&counter=34176×tamp=1137966043712
HTTP/1.1^M
Connection: close^M
Cookie: JSESSIONID=3404FCE146B94BA510AA5A10CAE18D9F^M
22:45:43.699368 IP iridium.sharpmind.de.43856 >
tc-chromium-ext.sharpmind.de.http-alt: P 0:406(406) ack 1 win 1460
[EMAIL PROTECTED]@.9.
..j
..
.P.......6].P....N..GET
/?gps_history=1337300;5251640;20;30;$&way_points=1342157;5238465;$&destination=784964;4799853;&cmd=navigate&version=1&counter=34176×tamp=1137966043712
HTTP/1.1^M
Connection: close^M
Cookie: JSESSIONID=3404FCE146B94BA510AA5A10CAE18D9F^M
So, it looks like JMeter, for some reason, is sending the request again.
Is there some circumstance when JMeter would send again a request
(perhaps after an internal timeout of 5 minutes has been reached?)
Also, what additional troubleshooting/investigation could I do?
JMeter.log does not indicate anything strange and the .jtl file used in
"Write All data to a File" in the Aggregate report writes the HTTP
request name but not the URL.
My environment is
JMeter 2.1.1
JDK 1.5.0
SuSE 9.3 client
Debian server
thanks
--
Ivan Rancati
SharpMind QA
---------------------------------------------------------------------
To unsubscribe, e-mail: [EMAIL PROTECTED]
For additional commands, e-mail: [EMAIL PROTECTED]
