Skip to content
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.

Sign up for GitHub

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

Jump to bottom

A dead-lock problem about HttpClientRequestImpl and Http1xClientConnection #453

Closed
BorisJineman opened this issue Apr 3, 2019 · 8 comments
Closed

A dead-lock problem about HttpClientRequestImpl and Http1xClientConnection #453

BorisJineman opened this issue Apr 3, 2019 · 8 comments
Assignees
@vietj
Labels
bug
Milestone
3.7.1

Comments

@BorisJineman
Copy link

BorisJineman commented Apr 3, 2019 •
edited

Hi team,

We were facing a dead lock problem when we use Vertx's HttpClient,
we searched this problem around, but not found any related documentations or discussions,

So I go here for seeking helps, hope team can help me to investigate it and check if there is any bugs.

Background
We want to pump an upper stream to a HTTP client's write stream.
So there are some codes like bellow,

          // Pump contents of upper stream to external service.
          inputReadStream.endHandler(_v -> httpRequest.end())
              .exceptionHandler(e -> failed.accept(true, e));
          Pump.pump(inputReadStream, httpRequest).start();

In the inputReadStream, The callback of endHandler might be executed in another context.

Problem
We identified a dead-lock in the httpRequest.end() method,

(vertx-blocked-thread-checker) 2019-04-02 17:08:27,172 [elements-indexer] WARN BlockedThreadChecker:55 - 
Thread Thread[vert.x-eventloop-thread-118,5,main] has been blocked for 87091863 ms, time limit is 2000 ms"
 io.vertx.core.VertxException: Thread blocked"
at io.vertx.core.http.impl.HttpClientRequestImpl.handleDrained(HttpClientRequestImpl.java:353)" -> dead lock at request.lock
at io.vertx.core.http.impl.Http1xClientConnection.handleInterestedOpsChanged(Http1xClientConnection.java:846)"
at io.vertx.core.net.impl.VertxHandler.lambda$channelWritabilityChanged$3(VertxHandler.java:136)"
at io.vertx.core.net.impl.VertxHandler$$Lambda$443/1659453903.handle(Unknown Source)"
...
at io.vertx.core.net.impl.ConnectionBase.write(ConnectionBase.java:102)" 
at io.vertx.core.net.impl.ConnectionBase.lambda$queueForWrite$0(ConnectionBase.java:123)" -> locked conn.lock 
at io.vertx.core.net.impl.ConnectionBase$$Lambda$371/2100884987.handle(Unknown Source)"
at io.vertx.core.impl.ContextImpl.executeTask(ContextImpl.java:320)"
at io.vertx.core.impl.EventLoopContext.lambda$executeAsync$0(EventLoopContext.java:38)"
...
at java.lang.Thread.run(Thread.java:748)"

and beside above dead-lock's log, we found another related dead-lock detection log as bellow,

 (vertx-blocked-thread-checker) 2019-04-02 17:08:27,164 [elements-indexer] WARN BlockedThreadChecker:55 - 
Thread Thread[vert.x-eventloop-thread-232,5,main] has been blocked for 87091863 ms, time limit is 2000 ms"
 io.vertx.core.VertxException: Thread blocked"
at io.vertx.core.http.impl.Http1xClientConnection$StreamImpl.endRequest(Http1xClientConnection.java:397)" -> dead-lock at conn.lock
at io.vertx.core.http.impl.HttpClientRequestImpl.write(HttpClientRequestImpl.java:653)" -> locked request.lock
at io.vertx.core.http.impl.HttpClientRequestImpl.end(HttpClientRequestImpl.java:576)"
at com.sorry.I cannot.tell.lambda$null$20(IndexServiceV2.java:339)"
at com.sorry.I cannot.tell$$Lambda$441/2034849463.handle(Unknown Source)"
at com.sorry.I cannot.tell.InputReadStream.handleEnd(InputReadStream.java:187)"
at com.sorry.I cannot.tell.InputReadStream.lambda$reportEndToClientIfEnd$1(InputReadStream.java:126)"
at com.sorry.I cannot.tell.InputReadStream$$Lambda$349/1412812725.handle(Unknown Source)"
at io.vertx.core.impl.ContextImpl.executeTask(ContextImpl.java:320)"
at io.vertx.core.impl.EventLoopContext.lambda$executeAsync$0(EventLoopContext.java:38)"
...
at java.lang.Thread.run(Thread.java:748)"

Investigation
We have a look into the codes of vertx, we found there are two locks,
one is in HttpClientRequestImpl class, it will lock itself,
and another one is in Http1xClientConnection and its parent class, it will also lock itself,

And we found if they are run in multi-thread together, the two locks might become dead-lock.

We drawn a diagram to explain what we saw,
image

Could team help us to investigate this and help us to check if there is a dead-lock problem in vertx?

Addition information,
Vert.X version: 3.6.2
@vietj
Copy link

vietj commented Apr 12, 2019

can you provide a reproducer ?

@vietj
Copy link

vietj commented Apr 12, 2019

can you re-open this issue in eclipse/vertx/vert.x repository ?

@vietj
Copy link

vietj commented Apr 12, 2019

I think this bug was fixed in vertx master, can you try with Vert.x 4.0 ?

@BorisJineman
Copy link
Author

Hi @vietj ,

I just created a test to reproduce this problem,
I tested with v3.7.0 v3.6.2 and the latest master branch in Vert.x repo,

This problem can be reproduced on both v3.7.0 and v3.6.2.
But the good news is that it CANNOT be reproduced with the codes on the latest branch (might be Vert.x 4.0).

So I think this problem should have been addressed in Vert.x 4.0. Thus, I think we can close this now.

Thank you for your help, and looking forward to Vert.x 4.0.

deadlockproblem.zip

@BorisJineman
Copy link
Author

(by the way, I'm not familiar with the processing of how to deal with issues registered at here. so who will click the close button of this issue?)

@vietj
Copy link

vietj commented Apr 13, 2019

thanks @BorisJineman I think I know which commit has been done in master that fixes the issue, I will use your reproducer as basis for writing a test.

it should be fixed in 3.7.1

@vietj
Copy link

vietj commented Apr 15, 2019

for record the full stack trace:

io.vertx.core.VertxException: Thread blocked
	at app//io.vertx.core.http.impl.HttpClientRequestImpl.handleDrained(HttpClientRequestImpl.java:353)
	at app//io.vertx.core.http.impl.Http1xClientConnection.handleInterestedOpsChanged(Http1xClientConnection.java:847)
	at app//io.vertx.core.net.impl.VertxHandler.lambda$channelWritabilityChanged$3(VertxHandler.java:136)
	at app//io.vertx.core.net.impl.VertxHandler$$Lambda$327/0x0000000800278840.handle(Unknown Source)
	at app//io.vertx.core.impl.ContextImpl.executeTask(ContextImpl.java:320)
	at app//io.vertx.core.impl.EventLoopContext.execute(EventLoopContext.java:43)
	at app//io.vertx.core.impl.ContextImpl.executeFromIO(ContextImpl.java:188)
	at app//io.vertx.core.impl.ContextImpl.executeFromIO(ContextImpl.java:180)
	at app//io.vertx.core.net.impl.VertxHandler.channelWritabilityChanged(VertxHandler.java:136)
	at app//io.netty.channel.AbstractChannelHandlerContext.invokeChannelWritabilityChanged(AbstractChannelHandlerContext.java:434)
	at app//io.netty.channel.AbstractChannelHandlerContext.invokeChannelWritabilityChanged(AbstractChannelHandlerContext.java:416)
	at app//io.netty.channel.AbstractChannelHandlerContext.fireChannelWritabilityChanged(AbstractChannelHandlerContext.java:409)
	at app//io.netty.channel.CombinedChannelDuplexHandler$DelegatingChannelHandlerContext.fireChannelWritabilityChanged(CombinedChannelDuplexHandler.java:450)
	at app//io.netty.channel.ChannelInboundHandlerAdapter.channelWritabilityChanged(ChannelInboundHandlerAdapter.java:119)
	at app//io.netty.channel.CombinedChannelDuplexHandler.channelWritabilityChanged(CombinedChannelDuplexHandler.java:273)
	at app//io.netty.channel.AbstractChannelHandlerContext.invokeChannelWritabilityChanged(AbstractChannelHandlerContext.java:434)
	at app//io.netty.channel.AbstractChannelHandlerContext.invokeChannelWritabilityChanged(AbstractChannelHandlerContext.java:416)
	at app//io.netty.channel.AbstractChannelHandlerContext.fireChannelWritabilityChanged(AbstractChannelHandlerContext.java:409)
	at app//io.netty.channel.DefaultChannelPipeline$HeadContext.channelWritabilityChanged(DefaultChannelPipeline.java:1457)
	at app//io.netty.channel.AbstractChannelHandlerContext.invokeChannelWritabilityChanged(AbstractChannelHandlerContext.java:434)
	at app//io.netty.channel.AbstractChannelHandlerContext.invokeChannelWritabilityChanged(AbstractChannelHandlerContext.java:416)
	at app//io.netty.channel.DefaultChannelPipeline.fireChannelWritabilityChanged(DefaultChannelPipeline.java:977)
	at app//io.netty.channel.ChannelOutboundBuffer.fireChannelWritabilityChanged(ChannelOutboundBuffer.java:607)
	at app//io.netty.channel.ChannelOutboundBuffer.setWritable(ChannelOutboundBuffer.java:573)
	at app//io.netty.channel.ChannelOutboundBuffer.decrementPendingOutboundBytes(ChannelOutboundBuffer.java:194)
	at app//io.netty.channel.ChannelOutboundBuffer.remove(ChannelOutboundBuffer.java:259)
	at app//io.netty.channel.ChannelOutboundBuffer.removeBytes(ChannelOutboundBuffer.java:338)
	at app//io.netty.channel.socket.nio.NioSocketChannel.doWrite(NioSocketChannel.java:428)
	at app//io.netty.channel.AbstractChannel$AbstractUnsafe.flush0(AbstractChannel.java:934)
	at app//io.netty.channel.nio.AbstractNioChannel$AbstractNioUnsafe.flush0(AbstractNioChannel.java:360)
	at app//io.netty.channel.AbstractChannel$AbstractUnsafe.flush(AbstractChannel.java:901)
	at app//io.netty.channel.DefaultChannelPipeline$HeadContext.flush(DefaultChannelPipeline.java:1396)
	at app//io.netty.channel.AbstractChannelHandlerContext.invokeFlush0(AbstractChannelHandlerContext.java:776)
	at app//io.netty.channel.AbstractChannelHandlerContext.invokeFlush(AbstractChannelHandlerContext.java:768)
	at app//io.netty.channel.AbstractChannelHandlerContext.flush(AbstractChannelHandlerContext.java:749)
	at app//io.netty.channel.CombinedChannelDuplexHandler$DelegatingChannelHandlerContext.flush(CombinedChannelDuplexHandler.java:533)
	at app//io.netty.channel.ChannelOutboundHandlerAdapter.flush(ChannelOutboundHandlerAdapter.java:115)
	at app//io.netty.channel.CombinedChannelDuplexHandler.flush(CombinedChannelDuplexHandler.java:358)
	at app//io.netty.channel.AbstractChannelHandlerContext.invokeFlush0(AbstractChannelHandlerContext.java:776)
	at app//io.netty.channel.AbstractChannelHandlerContext.invokeWriteAndFlush(AbstractChannelHandlerContext.java:802)
	at app//io.netty.channel.AbstractChannelHandlerContext.write(AbstractChannelHandlerContext.java:814)
	at app//io.netty.channel.AbstractChannelHandlerContext.writeAndFlush(AbstractChannelHandlerContext.java:794)
	at app//io.vertx.core.net.impl.ConnectionBase.write(ConnectionBase.java:102)
	at app//io.vertx.core.net.impl.ConnectionBase.lambda$queueForWrite$0(ConnectionBase.java:123)
	at app//io.vertx.core.net.impl.ConnectionBase$$Lambda$326/0x0000000800279440.handle(Unknown Source)
	at app//io.vertx.core.impl.ContextImpl.executeTask(ContextImpl.java:320)
	at app//io.vertx.core.impl.EventLoopContext.lambda$executeAsync$0(EventLoopContext.java:38)
	at app//io.vertx.core.impl.EventLoopContext$$Lambda$289/0x0000000800203840.run(Unknown Source)
	at app//io.netty.util.concurrent.AbstractEventExecutor.safeExecute(AbstractEventExecutor.java:163)
	at app//io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:404)
	at app//io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:462)
	at app//io.netty.util.concurrent.SingleThreadEventExecutor$5.run(SingleThreadEventExecutor.java:897)
	at app//io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
	at java.base@11/java.lang.Thread.run(Thread.java:834)

@vietj vietj self-assigned this Apr 15, 2019
@vietj vietj added the bug label Apr 15, 2019
@vietj vietj added this to the 3.7.1 milestone Apr 15, 2019
@vietj
Copy link

vietj commented Apr 15, 2019

see eclipse-vertx/vert.x#2907

@vietj vietj closed this as completed May 6, 2019
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@vietj vietj

Labels
bug
Milestone
3.7.1
Development

No branches or pull requests
2 participants
@vietj @BorisJineman