Bug 60444 - Intermittent failure of TestHTTPMirrorThread#testSleep()
Summary: Intermittent failure of TestHTTPMirrorThread#testSleep()
Status: RESOLVED FIXED
Alias: None
Product: JMeter
Classification: Unclassified
Component: HTTP (show other bugs)
Version: 3.0
Hardware: PC All
: P2 minor (vote)
Target Milestone: ---
Assignee: JMeter issues mailing list
URL:
Keywords:
Depends on:
Blocks:
 
Reported: 2016-12-05 21:34 UTC by Thomas Schapitz
Modified: 2016-12-21 15:26 UTC (History)
1 user (show)



Attachments
complete log of ant build (1 bytes, text/plain)
2016-12-05 21:34 UTC, Thomas Schapitz
Details
ant log (17.73 KB, text/plain)
2016-12-14 17:45 UTC, Thomas Schapitz
Details
Patch as promissed. (1.21 KB, patch)
2016-12-21 14:10 UTC, Thomas Schapitz
Details | Diff

Note You need to log in before you can comment on or make changes to this bug.
Description Thomas Schapitz 2016-12-05 21:34:54 UTC
Created attachment 34500 [details]
complete log of ant build

This might be OS specific: Running the tests, I'm occasionally stalled by the following test failure:

     [java] There was 1 failure:
     [java] 1) testSleep(org.apache.jmeter.protocol.http.control.TestHTTPMirrorThread)
     [java] junit.framework.AssertionFailedError: Expected > 1000 992
     [java]     at junit.framework.Assert.fail(Assert.java:57)
     [java]     at junit.framework.Assert.assertTrue(Assert.java:22)
     [java]     at junit.framework.TestCase.assertTrue(TestCase.java:192)
     [java]     at org.apache.jmeter.protocol.http.control.TestHTTPMirrorThread.testSleep(TestHTTPMirrorThread.java:413)

I'm not too certain about the primary cause, which I think, is one of the following:
a.) Thread.sleep() relies on the granularity of the internal clock, which might shave off some millis from the 1000 ms, that have been asked for.
b.) The JVM generally isn't guaranteed to wait the full time given anyway, as the sleep might get interrupted.

Now I'm a bit at a loss, what is the intention here: 
If accuracy in maintaining the contract is required, I may fix this, by tracking the actual time spent waiting arround the invocation of
    TimeUnit.MILLISECONDS.sleep(Integer.parseInt(sleepHeaderValue))
@ HttpMirrorThread:223.

else we might just relax the assertion wihin the test.

Do we ever need this functionality?


Wadayathink?

P.S.:
The issue is annoying, since it breaks the test execution in one out of three executions on my machine, and it did so since I startet to dig through the code with Rel 3.0
Comment 1 Felix Schumacher 2016-12-06 21:00:51 UTC
On what computer do you see these failures?

I think it might help to put the now=System.nanoTime() before the conn.connect().

And by the way the attached log is only one byte long.
Comment 2 Thomas Schapitz 2016-12-14 17:45:44 UTC
Created attachment 34525 [details]
ant log

Sorry about the log, there it is now.

Anyway, it's only puting the stacktrace into some context. This happens on a Windows 10 Notebook, both when running with JDK 1.7.0 or 1.8.0.

From my point of view, the current position of now = System.nanoTime() is quite right. Placing it earlier is equivalent of adding some time, since the server side method will not get executed, until either getInputStream() or getOutputStream() are called, *and* the streams are read from or written to - thats at least what I took from various internet posts about the HttpUrlConnection. You might want to convince yourself by placing breakpoints into the test and the serverside method.

My questions are on a different tack: 
- What are we trying to achieve by the test?

which also relates to the question:
- what is the use case of a server side wait in a JMeter HTTP-Mirror?
Comment 3 Thomas Schapitz 2016-12-17 11:53:36 UTC
If checked up on my previous statement, and have to correct:
connect() actually does initiate the roundtrip to the server, at least for the Sun implementation of the HttpUrlConnection.

Thus, we should indeed start taking time before the connect(). I'm going to supply a patch for this, which should mitigate the woes.

However I would like to point out that this still isn't a healthy aproach: 
sleep() throws an InterruptedException, which is apart from a log statement silently swallowed, so the test does hinge on the assumption, that there are no spourious interruptions.
Comment 4 Felix Schumacher 2016-12-17 12:23:28 UTC
Thanks for your further analysis.

Perhaps let the server return a result code/string, that could be parsed in the test method and checked for an (Interrupted)Exception?
Comment 5 Thomas Schapitz 2016-12-21 14:10:43 UTC
@Felix: I'm, already shaving the yak here - my intention was just to get the tests going again.
Introducing additional erromessages, albeit sensible, invites compatibility trouble down the line.
Comment 6 Thomas Schapitz 2016-12-21 14:10:50 UTC
Created attachment 34542 [details]
Patch as promissed.
Comment 7 Philippe Mouawad 2016-12-21 15:26:05 UTC
Thanks for contribution.


Date: Wed Dec 21 15:25:34 2016
New Revision: 1775470

URL: http://svn.apache.org/viewvc?rev=1775470&view=rev
Log:
Bug 60444 - Intermittent failure of TestHTTPMirrorThread#testSleep()
Bugzilla Id: 60444

Modified:
    jmeter/trunk/test/src/org/apache/jmeter/protocol/http/control/TestHTTPMirrorThread.java
    jmeter/trunk/xdocs/changes.xml