Frequent timeouts on contract call

[cristinaGroapaCGI]

Hello. I am using web3j-quorum to run contract transactions on a private ethereum quorum.
Quite often (every few transactions) I see the request timing out.

web3j stacktrace:
java.net.SocketException: Connection timed out (Read failed) at java.net.SocketInputStream.socketRead0(Native Method) ~[na:1.8.0_121] at java.net.SocketInputStream.socketRead(SocketInputStream.java:116) ~[na:1.8.0_121] at java.net.SocketInputStream.read(SocketInputStream.java:171) ~[na:1.8.0_121] at java.net.SocketInputStream.read(SocketInputStream.java:141) ~[na:1.8.0_121] at org.apache.http.impl.io.SessionInputBufferImpl.streamRead(SessionInputBufferImpl.java:137) ~[httpcore-4.4.6.jar:4.4.6] at org.apache.http.impl.io.SessionInputBufferImpl.fillBuffer(SessionInputBufferImpl.java:153) ~[httpcore-4.4.6.jar:4.4.6] at org.apache.http.impl.io.SessionInputBufferImpl.readLine(SessionInputBufferImpl.java:282) ~[httpcore-4.4.6.jar:4.4.6] at org.apache.http.impl.conn.DefaultHttpResponseParser.parseHead(DefaultHttpResponseParser.java:138) ~[httpclient-4.5.3.jar:4.5.3] at org.apache.http.impl.conn.DefaultHttpResponseParser.parseHead(DefaultHttpResponseParser.java:56) ~[httpclient-4.5.3.jar:4.5.3] at org.apache.http.impl.io.AbstractMessageParser.parse(AbstractMessageParser.java:259) ~[httpcore-4.4.6.jar:4.4.6] at org.apache.http.impl.DefaultBHttpClientConnection.receiveResponseHeader(DefaultBHttpClientConnection.java:163) ~[httpcore-4.4.6.jar:4.4.6] at org.apache.http.impl.conn.CPoolProxy.receiveResponseHeader(CPoolProxy.java:165) ~[httpclient-4.5.3.jar:4.5.3] at org.apache.http.protocol.HttpRequestExecutor.doReceiveResponse(HttpRequestExecutor.java:273) ~[httpcore-4.4.6.jar:4.4.6] at org.apache.http.protocol.HttpRequestExecutor.execute(HttpRequestExecutor.java:125) ~[httpcore-4.4.6.jar:4.4.6] at org.apache.http.impl.execchain.MainClientExec.execute(MainClientExec.java:272) ~[httpclient-4.5.3.jar:4.5.3] at org.apache.http.impl.execchain.ProtocolExec.execute(ProtocolExec.java:185) ~[httpclient-4.5.3.jar:4.5.3] at org.apache.http.impl.execchain.RetryExec.execute(RetryExec.java:89) ~[httpclient-4.5.3.jar:4.5.3] at org.apache.http.impl.execchain.RedirectExec.execute(RedirectExec.java:111) ~[httpclient-4.5.3.jar:4.5.3] at org.apache.http.impl.client.InternalHttpClient.doExecute(InternalHttpClient.java:185) ~[httpclient-4.5.3.jar:4.5.3] at org.apache.http.impl.client.CloseableHttpClient.execute(CloseableHttpClient.java:72) ~[httpclient-4.5.3.jar:4.5.3] at org.apache.http.impl.client.CloseableHttpClient.execute(CloseableHttpClient.java:221) ~[httpclient-4.5.3.jar:4.5.3] at org.apache.http.impl.client.CloseableHttpClient.execute(CloseableHttpClient.java:165) ~[httpclient-4.5.3.jar:4.5.3] at org.apache.http.impl.client.CloseableHttpClient.execute(CloseableHttpClient.java:140) ~[httpclient-4.5.3.jar:4.5.3] at org.web3j.protocol.http.HttpService.send(HttpService.java:67) ~[core-2.3.0.jar:na] at org.web3j.protocol.core.Request.send(Request.java:69) ~[core-2.3.0.jar:na] at org.web3j.quorum.tx.ClientTransactionManager.sendTransaction(ClientTransactionManager.java:64) ~[quorum-0.5.0.jar:na] at org.web3j.tx.TransactionManager.executeTransaction(TransactionManager.java:45) ~[core-2.3.0.jar:na] at org.web3j.tx.ManagedTransaction.send(ManagedTransaction.java:43) ~[core-2.3.0.jar:na] at org.web3j.tx.Contract.executeTransaction(Contract.java:207) ~[core-2.3.0.jar:na] at org.web3j.tx.Contract.executeTransaction(Contract.java:187) ~[core-2.3.0.jar:na] at org.web3j.tx.Contract.lambda$executeTransactionAsync$23(Contract.java:217) ~[core-2.3.0.jar:na] at org.web3j.utils.Async.lambda$run$29(Async.java:22) ~[core-2.3.0.jar:na] at java.util.concurrent.CompletableFuture$AsyncRun.run(CompletableFuture.java:1626) ~[na:1.8.0_121] at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) ~[na:1.8.0_121] at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) ~[na:1.8.0_121] at java.lang.Thread.run(Thread.java:745) [na:1.8.0_121]

tcpdump snippet:
`{"jsonrpc":"2.0","method":"eth_sendTransaction","params":[{"from":"0x5f9adb57d37f0044273b68b3ca20cb8bd3a1a407","to":"0xb66892a511aeb2833d17d8310c03a6c941851506","gas":"0xf4240","value":"0x0","data":"0xf6aa33e1000000000000000000000000c072fa2b03a952771c456f43cf14cbce1d3587b600000000000000000000000000000000000000000000000000000000000000c8","privateFor":[]}],"id":1}
12:25:52.135102 IP 192.168.140.155.47170 > x.x.x.x.8545: Flags [P.], seq 0:613, ack 1, win 482, options [nop,nop,TS val 18147871 ecr 191192547], length 613
E.....@.@.......4.2 .B!a.............D.....
.....e].POST / HTTP/1.1
Content-Type: application/json; charset=UTF-8
Content-Length: 364
Host: rbcqa246k.northeurope.cloudapp.azure.com:8545
Connection: Keep-Alive
User-Agent: Apache-HttpClient/4.5.3 (Java/1.8.0_121)
Accept-Encoding: gzip,deflate

{"jsonrpc":"2.0","method":"eth_sendTransaction","params":[{"from":"0x5f9adb57d37f0044273b68b3ca20cb8bd3a1a407","to":"0xb66892a511aeb2833d17d8310c03a6c941851506","gas":"0xf4240","value":"0x0","data":"0xf6aa33e1000000000000000000000000c072fa2b03a952771c456f43cf14cbce1d3587b600000000000000000000000000000000000000000000000000000000000000c8","privateFor":[]}],"id":1}
12:25:52.355233 IP 192.168.140.155.47170 > x.x.x.x.8545: Flags [P.], seq 0:613, ack 1, win 482, options [nop,nop,TS val 18147926 ecr 191192547], length 613
E.....@.@.......4.2 .B!a...................
...V.e].POST / HTTP/1.1
Content-Type: application/json; charset=UTF-8
Content-Length: 364
Host: rbcqa246k.northeurope.cloudapp.azure.com:8545
Connection: Keep-Alive
User-Agent: Apache-HttpClient/4.5.3 (Java/1.8.0_121)
Accept-Encoding: gzip,deflate

The above repeats many times without response.
Is there anything I may be doing wrong? I am using a single TransactionManager, Quorum and Contract object throughout the lifetime of the service if it makes any difference.

Thanks.

[conor10]

How is the Quorum network being run - i.e. within a Vagrant environment, or with Quorum nodes deployed to dedicated hosts?

[cristinaGroapaCGI]

It's deployed in Quorum nodes in VMs running in Azure. There's no use of Vagrant.

Also I should have mentioned I'm using:
GAS PRICE = 0
GAS LIMIT= 1 000 000

And I've seen this behaviour (less frequently) on a contract read too, not just on transactions.

[cristinaGroapaCGI]

Timeout scenario:

• run some transactions on a contract
• wait for a few minutes
• run another transaction on the contract -> usually times out

I've made a comparison between geth, curl to JSON RPC, and web3j based on tcpdump. I can see that only web3j uses Connection: Keep-alive header. So I disabled connection re-use in Apache httpclient (http.keepAlive=false). This seems to have fixed the problem (not heavily tested yet).

Was this behaviour seen before? It brings up again the question about object lifespan - I am using a single Quorum and TransactionManager (and thus a single CloseableHttpClient) throughout the service lifecycle. Is this the recommended way? Is there any possibility that the singleton model doesn't handle connections properly?

I will get back with updates after more thorough testing.

[conor10]

Thanks @cristinaGroapaCGI. You are the first person to report this issue. What sort of transaction throughput are you performing?

I've migrated web3j across to use OkHttp instead of HttpClient, but haven't got the release out just yet. As OkHttp uses pooled connections it won't necessarily resolve the issue, but it will be good to see if the problem still exists there.

[cristinaGroapaCGI]

The throughput is very low, at any given time there's at most one transaction; maybe a few dozens a day (no automated tests yet). I can confirm now that the above (http.keepAlive=false) does fix the issue.

I noticed the OkHttp switch. I will pull the latest and give it a go. Thanks!

[conor10]

Could there be any infrastructure between the application using web3j and the Azure nodes that was terminating the TCP connection? Given the low transaction throughput, I would expect this issue to have appeared elsewhere if it was an underlying issue with web3j.

[SenthuranSivananthan]

@conor10, there aren't any intermediate components. It's a simple deployment with 1 block maker and 1 voter node, both deployed inside a single virtual network and there are no firewall devices or services that's terminating connections intermittently.

[cristinaGroapaCGI]

The OkHttp version seems to do the trick, I wasn't able to reproduce the timeouts.
@conor10 Do you have an estimate of when the next release will be to include OkHttp?

[conor10]

Sorry - meant to say, the OkHttp version was released last month.

I've just put 0.8.0 out, please use this version going forwards.

[codingEcho]

@cristinaGroapaCGI @conor10 I had the same problem，when I call contract

java.net.SocketTimeoutException: timeout
        at okio.Okio$4.newTimeoutException(Okio.java:230)
        at okio.AsyncTimeout.exit(AsyncTimeout.java:285)
        at okio.AsyncTimeout$2.read(AsyncTimeout.java:241)
        at okio.RealBufferedSource.indexOf(RealBufferedSource.java:345)
        at okio.RealBufferedSource.readUtf8LineStrict(RealBufferedSource.java:217)
        at okio.RealBufferedSource.readUtf8LineStrict(RealBufferedSource.java:211)
        at okhttp3.internal.http1.Http1Codec.readResponseHeaders(Http1Codec.java:189)
        at okhttp3.internal.http.CallServerInterceptor.intercept(CallServerInterceptor.java:75)
        at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:92)
        at okhttp3.internal.connection.ConnectInterceptor.intercept(ConnectInterceptor.java:45)
        at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:92)
        at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:67)
        at okhttp3.internal.cache.CacheInterceptor.intercept(CacheInterceptor.java:93)
        at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:92)
        at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:67)
        at okhttp3.internal.http.BridgeInterceptor.intercept(BridgeInterceptor.java:93)
        at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:92)
        at okhttp3.internal.http.RetryAndFollowUpInterceptor.intercept(RetryAndFollowUpInterceptor.java:120)
        at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:92)
        at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:67)
        at okhttp3.RealCall.getResponseWithInterceptorChain(RealCall.java:185)
        at okhttp3.RealCall.execute(RealCall.java:69)
        at org.web3j.protocol.http.HttpService.performIO(HttpService.java:104)
        at org.web3j.protocol.Service.send(Service.java:31)
        at org.web3j.protocol.core.Request.send(Request.java:71)
        at org.web3j.tx.ClientTransactionManager.sendTransaction(ClientTransactionManager.java:49)
        at org.web3j.tx.TransactionManager.executeTransaction(TransactionManager.java:49)
        at org.web3j.tx.ManagedTransaction.send(ManagedTransaction.java:70)
        at org.web3j.tx.Contract.executeTransaction(Contract.java:223)
        at org.web3j.tx.Contract.executeTransaction(Contract.java:207)
        at org.web3j.tx.Contract.executeTransaction(Contract.java:201)
        at org.web3j.tx.Contract.lambda$executeRemoteCallTransaction$3(Contract.java:240)
        at org.web3j.protocol.core.RemoteCall.send(RemoteCall.java:30)

[johnmmcparland]

@codingEcho - @cristinaGroapaCGI and I didn't have the same problem with the OkHttp version of web3j quorum but that was back in September when we were last using it in anger (see above post).

@Nikhil-Shekhawat - do you know if there was any further problems?