Spurious ReactiveStreamsTest#testConnectionDoesNotGetClosed failure #1380

slandelle · 2017-03-29T09:14:00Z

Reproducer: org.asynchttpclient.reactivestreams.ReactiveStreamsTest#main (might have to run several times):

testConnectionDoesNotGetClosed(org.asynchttpclient.reactivestreams.ReactiveStreamsTest)  Time elapsed: 0.342 sec  <<< FAILURE!
java.lang.AssertionError:  expected [[B@95f1422] but found [[B@31b7112d]
	at org.asynchttpclient.reactivestreams.ReactiveStreamsTest.testConnectionDoesNotGetClosed(ReactiveStreamsTest.java:66)

The text was updated successfully, but these errors were encountered:

farmdawgnation · 2017-07-03T18:51:20Z

I checked the most recent build from Travis.

I found this buried in the logs.

Results :

Failed tests: 
  BasicHttpsTest.multipleSequentialPostRequestsOverHttps:95->lambda$multipleSequentialPostRequestsOverHttps$5:96->lambda$null$4:105 expected [hello there] but found [<html>
<head>
<meta http-equiv="Content-Type" content="text/html;charset=utf-8"/>
<title>Error 500 No handler enqueued</title>
</head>
<body><h2>HTTP ERROR 500</h2>
<p>Problem accessing /foo/bar. Reason:
<pre>    No handler enqueued</pre></p><hr><a href="http://eclipse.org/jetty">Powered by Jetty:// 9.4.6.v20170531</a><hr/>
</body>
</html>
]

  ReactiveStreamsTest.testConnectionDoesNotGetClosed:256 Invalid response byte at position 12000 expected [111] but found [45]

I'm not sure, but it looks like there's more than one issue going on here...

slandelle · 2017-07-05T11:10:08Z

I'm pretty sure I got the BasicHttpsTest.multipleSequentialPostRequestsOverHttps failure pinned, see #1434

But sadly, it's completely unrelated to the ReactiveStreamsTest.testConnectionDoesNotGetClosed one :(

slandelle · 2017-07-05T11:26:40Z

I can get ReactiveStreamsTest#main to fail almost every time on my machine:

Request DefaultHttpRequest(decodeResult: success, version: HTTP/1.1)
PUT /foo/test HTTP/1.1
X-content-length: 265495
X-content-md5: sBFA+zEHvFHWTKspPX86Gg==
transfer-encoding: chunked
host: localhost:62655
accept: */*
user-agent: AHC/2.1

Response DefaultHttpResponse(decodeResult: success, version: HTTP/1.1)
HTTP/1.1 200 
X-x-content-length: 265495
X-x-content-md5: sBFA+zEHvFHWTKspPX86Gg==
X-transfer-encoding: chunked
X-host: localhost:62655
X-accept: */*
X-user-agent: AHC/2.1
X-pathInfo: /foo/test
X-KEEP-ALIVE: 127.0.0.1:62713
X-content-length: 265495
content-md5: BJhrrx4cp/H3htzVPIJGIg==
Content-Type: text/html;charset=UTF-8
Transfer-Encoding: chunked
Date: Wed, 05 Jul 2017 11:25:16 GMT

2017-07-05 13:25:17,842 [AsyncHttpClient-60-1] DEBUG org.asynchttpclient.netty.channel.ChannelManager - Adding key: http://localhost:62655 for channel [id: 0xbafe3c5f, L:/127.0.0.1:62713 - R:localhost/127.0.0.1:62655]
java.lang.AssertionError: Server side payload MD5 invalid expected [sBFA+zEHvFHWTKspPX86Gg==] but found [BJhrrx4cp/H3htzVPIJGIg==]
	at org.testng.Assert.fail(Assert.java:94)
	at org.testng.Assert.failNotEquals(Assert.java:513)
	at org.testng.Assert.assertEqualsImpl(Assert.java:135)
	at org.testng.Assert.assertEquals(Assert.java:116)
	at org.testng.Assert.assertEquals(Assert.java:190)
	at org.asynchttpclient.reactivestreams.ReactiveStreamsTest.testConnectionDoesNotGetClosed(ReactiveStreamsTest.java:260)
	at org.asynchttpclient.reactivestreams.ReactiveStreamsTest.main(ReactiveStreamsTest.java:278)
2017-07-05 13:25:17,853 [main] INFO org.apache.coyote.http11.Http11NioProtocol - Pausing ProtocolHandler ["http-nio-auto-1-62655"]
2017-07-05 13:25:17,861 [main] INFO org.apache.catalina.core.StandardService - Stopping service Tomcat
2017-07-05 13:25:17,871 [main] INFO org.apache.coyote.http11.Http11NioProtocol - Stopping ProtocolHandler ["http-nio-auto-1-62655"]
Exception in thread "main" java.lang.AssertionError: Invalid response byte at position 12000 expected [111] but found [45]
	at org.testng.Assert.fail(Assert.java:94)
	at org.testng.Assert.failNotEquals(Assert.java:513)
	at org.testng.Assert.assertEqualsImpl(Assert.java:135)
	at org.testng.Assert.assertEquals(Assert.java:116)
	at org.testng.Assert.assertEquals(Assert.java:326)
	at org.asynchttpclient.reactivestreams.ReactiveStreamsTest.testConnectionDoesNotGetClosed(ReactiveStreamsTest.java:266)
	at org.asynchttpclient.reactivestreams.ReactiveStreamsTest.main(ReactiveStreamsTest.java:278)

farmdawgnation · 2017-07-18T00:31:49Z

I've been thinking about this failure for a few days now and still can't figure out what would be causing this. What's the exact command you're running?

slandelle · 2017-07-18T05:46:25Z

I just run main method from IntelliJ.

farmdawgnation · 2017-07-19T02:09:29Z

Ah, there's a main method in the unit test. I was just running the test from mvn on the command line. Let me try that.

farmdawgnation · 2017-07-19T03:17:00Z

Okay, I was able to reproduce the failure. I don't have a solution here yet but I think I've learned some interesting things:

It doesn't behave like a race condition. I can't fix it using arbitrary Thread.sleeps in the test or in the test server.
The failure is always the same:
- It occurs at offset 12,000 in the byte array
- It always expects byte 111 in that position but finds byte 45.
- Bytes after this position appear to be wrong too.

Position 12000 is exactly at 12 kilobytes. Is that a magic number of a buffer somewhere important?

farmdawgnation · 2017-07-19T03:26:47Z

Oh. Also. When the entire content fails it fails the same way. The MD5 of the bad response is the same each time.

slandelle · 2017-07-19T08:06:55Z

It occurs at offset 12,000 in the byte array

I've seen it happen at offset 24,000 too

12000 bytes is not 12kb :)

The problem is not server side as I was able to reproduce with Jetty, Netty and Tomcat.

12000 has not be some buffer size, either in Netty or kernel but I wasn't able to spot it. It happens on OSX (my machine) and Linux (Travis).

No idea what happens. Looks like buffer corruption.

farmdawgnation · 2017-07-19T12:16:35Z

I'm inclined to say the same. The fact that it's the same failure every time on my machine is just weird though.

In any event I'm skeptical that the bug is in AHC. Might be worthwhile to try playing with the underlying Netty version to see if the problem disappears. Have you done that yet?

slandelle · 2017-07-20T12:11:12Z

Might be worthwhile to try playing with the underlying Netty version to see if the problem disappears. Have you done that yet?

I can reproduce with Netty 4.1.0.Final. I didn't bother digging further.

In any event I'm skeptical that the bug is in AHC.

This feature involves many libs:

AHC itself
netty
netty-reactive-streams
rxjava
rxjava-reactive-streams

Hard to figure out where issue might happen.
I've checked netty-reactive-streams sources and couldn't spot an issue.

farmdawgnation · 2017-07-21T13:30:54Z

Can we backport this test to an earlier version of AHC?

My thought on this is that if AHC 2.0 exhibits the same bug then this isn't a regression and we should feel free to move forward releasing AHC 2.1.

slandelle · 2017-07-22T08:33:05Z

Can we backport this test to an earlier version of AHC?

It fails too on AHC 2.0

My thought on this is that if AHC 2.0 exhibits the same bug then this isn't a regression and we should feel free to move forward releasing AHC 2.1.

I currently have no idea if this bug is only limited to reactivestreams based features or if it's a critical issue that just happened to be spotted here. I don't feel comfortable releasing the next stable version with such doubt lurking around.

farmdawgnation · 2017-07-22T16:17:10Z

I currently have no idea if this bug is only limited to reactivestreams based features or if it's a critical issue that just happened to be spotted here.

I don't know the codebase well enough to answer this question for sure, but the surface area of AHC itself on the critical path for this feature seems relatively small to me. The fact that it fails, too, on AHC 2.0 means that in your shoes I'd probably release the code with a Known Bug caveat in the release notes. That is just me, however.

I don't have time this weekend, but perhaps next weekend I'll have time to dig in and see if I can play with dependencies and determine whether or not changing netty versions and such causes the problem to disappear.

slandelle · 2017-07-24T20:09:50Z

@farmdawgnation Please give it a try. I'm pretty sure it was a RxJava 1 bug that was fixed in RxJava 2. There are other foobar stuffs related to reactive streams that I want to clean up before releasing 2.1. I'll work on this when I'll be back from vacation.

farmdawgnation · 2017-07-25T23:46:48Z

Huzzah! It seems to resolved the issue on my end, too!

slandelle · 2017-07-27T12:36:20Z

Great, thanks for the feedback!

slandelle · 2017-11-28T08:15:08Z

Issue still happens almost every time on Travis.
I think I have a clue: playframework/netty-reactive-streams#37

I think Subscription is being sometimes requested from 2 different threads: from the calling thread and from the channel's event loop. When such switch happen, I think chunks can be written out of order as the ones read from the calling thread have to jump into the event loop.

slandelle added the Defect label Mar 29, 2017

slandelle added a commit that referenced this issue Mar 30, 2017

Try to get more information, see #1380

3e6e6e1

slandelle mentioned this issue Jun 8, 2017

Added retrofit2 module. #1419

Merged

ssoloff mentioned this issue Jun 9, 2017

Fix broken Head302Test #1421

Merged

farmdawgnation mentioned this issue Jul 3, 2017

Trying to figure out what's up with the tests #1433

Merged

slandelle pushed a commit that referenced this issue Jul 5, 2017

Adding some more detail to the ReactiveStreamsTest, see #1380

8dae6b6

slandelle closed this as completed in 271a3b4 Jul 24, 2017

HKrausAxon mentioned this issue Sep 15, 2017

Immediately close channel when subscribers cancel #1458

Closed

slandelle reopened this Nov 28, 2017

slandelle closed this as completed in 391b4d8 Nov 28, 2017

slandelle self-assigned this Dec 12, 2017

slandelle added this to the 2.1.0 milestone Dec 12, 2017

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Spurious ReactiveStreamsTest#testConnectionDoesNotGetClosed failure #1380

Spurious ReactiveStreamsTest#testConnectionDoesNotGetClosed failure #1380

slandelle commented Mar 29, 2017 •

edited

Loading

farmdawgnation commented Jul 3, 2017 •

edited by slandelle

Loading

slandelle commented Jul 5, 2017

slandelle commented Jul 5, 2017

farmdawgnation commented Jul 18, 2017

slandelle commented Jul 18, 2017

farmdawgnation commented Jul 19, 2017

farmdawgnation commented Jul 19, 2017

farmdawgnation commented Jul 19, 2017

slandelle commented Jul 19, 2017

farmdawgnation commented Jul 19, 2017

slandelle commented Jul 20, 2017

farmdawgnation commented Jul 21, 2017

slandelle commented Jul 22, 2017

farmdawgnation commented Jul 22, 2017

slandelle commented Jul 24, 2017

farmdawgnation commented Jul 25, 2017

slandelle commented Jul 27, 2017

slandelle commented Nov 28, 2017

Spurious ReactiveStreamsTest#testConnectionDoesNotGetClosed failure #1380

Spurious ReactiveStreamsTest#testConnectionDoesNotGetClosed failure #1380

Comments

slandelle commented Mar 29, 2017 • edited Loading

farmdawgnation commented Jul 3, 2017 • edited by slandelle Loading

slandelle commented Jul 5, 2017

slandelle commented Jul 5, 2017

farmdawgnation commented Jul 18, 2017

slandelle commented Jul 18, 2017

farmdawgnation commented Jul 19, 2017

farmdawgnation commented Jul 19, 2017

farmdawgnation commented Jul 19, 2017

slandelle commented Jul 19, 2017

farmdawgnation commented Jul 19, 2017

slandelle commented Jul 20, 2017

farmdawgnation commented Jul 21, 2017

slandelle commented Jul 22, 2017

farmdawgnation commented Jul 22, 2017

slandelle commented Jul 24, 2017

farmdawgnation commented Jul 25, 2017

slandelle commented Jul 27, 2017

slandelle commented Nov 28, 2017

slandelle commented Mar 29, 2017 •

edited

Loading

farmdawgnation commented Jul 3, 2017 •

edited by slandelle

Loading