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.

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

Intermittent HTTP Sender "failed to respond" errors in 3.4 #3840

Closed
rbeckman-nextgen opened this issue May 11, 2020 · 5 comments
Closed

Intermittent HTTP Sender "failed to respond" errors in 3.4 #3840

rbeckman-nextgen opened this issue May 11, 2020 · 5 comments
Milestone

Comments

@rbeckman-nextgen
Copy link
Collaborator

@rbeckman-nextgen rbeckman-nextgen commented May 11, 2020

It appears this was caused by the updated version of Apache HttpComponents HttpClient we're using (4.5.1). If the server drops a connection, the client may not be aware of it until it actually tries to use the socket. Apparently the newer version does not automatically check for server-side closures, so if you send a message a while after the server has closed its side, you'll get something like this:

HTTP Sender error ERROR MESSAGE: Error connecting to HTTP server org.apache.http.NoHttpResponseException: localhost:9001 failed to respond at org.apache.http.impl.conn.DefaultHttpResponseParser.parseHead(DefaultHttpResponseParser.java:143) at org.apache.http.impl.conn.DefaultHttpResponseParser.parseHead(DefaultHttpResponseParser.java:57) at org.apache.http.impl.io.AbstractMessageParser.parse(AbstractMessageParser.java:261) at org.apache.http.impl.DefaultBHttpClientConnection.receiveResponseHeader(DefaultBHttpClientConnection.java:165) at org.apache.http.protocol.HttpRequestExecutor.doReceiveResponse(HttpRequestExecutor.java:272) at org.apache.http.protocol.HttpRequestExecutor.execute(HttpRequestExecutor.java:124) at org.apache.http.impl.execchain.MainClientExec.execute(MainClientExec.java:271) at org.apache.http.impl.execchain.ProtocolExec.execute(ProtocolExec.java:184) at org.apache.http.impl.execchain.RetryExec.execute(RetryExec.java:88) at org.apache.http.impl.execchain.RedirectExec.execute(RedirectExec.java:110) at org.apache.http.impl.client.InternalHttpClient.doExecute(InternalHttpClient.java:184) at org.apache.http.impl.client.CloseableHttpClient.execute(CloseableHttpClient.java:71) at com.mirth.connect.connectors.http.HttpDispatcher.send(HttpDispatcher.java:318) at com.mirth.connect.donkey.server.channel.DestinationConnector.handleSend(DestinationConnector.java:778) at com.mirth.connect.donkey.server.channel.DestinationConnector.process(DestinationConnector.java:437) at com.mirth.connect.donkey.server.channel.DestinationChain.doCall(DestinationChain.java:121) at com.mirth.connect.donkey.server.channel.DestinationChain.call(DestinationChain.java:63) at com.mirth.connect.donkey.server.channel.Channel.process(Channel.java:1706) at com.mirth.connect.donkey.server.channel.Channel.dispatchRawMessage(Channel.java:1189) at com.mirth.connect.donkey.server.channel.SourceConnector.dispatchRawMessage(SourceConnector.java:192) at com.mirth.connect.server.controllers.DonkeyEngineController.dispatchRawMessage(DonkeyEngineController.java:1052) at com.mirth.connect.server.api.servlets.MessageServlet$2.run(MessageServlet.java:106) at java.lang.Thread.run(Thread.java:745)

Imported Issue. Original Details:
Jira Issue Key: MIRTH-3962
Reporter: narupley
Created: 2016-05-17T13:33:04.000-0700

@rbeckman-nextgen rbeckman-nextgen added this to the 3.4.1 milestone May 11, 2020
@rbeckman-nextgen
Copy link
Collaborator Author

@rbeckman-nextgen rbeckman-nextgen commented May 11, 2020

To reproduce this, set up an HTTP Sender and Listener, where the former sends to the latter. Send a message to the sender channel. Then stop the listener, and wait a minute or so. Then send another message to the sender channel.

Imported Comment. Original Details:
Author: narupley
Created: 2016-05-17T13:34:25.000-0700

@rbeckman-nextgen
Copy link
Collaborator Author

@rbeckman-nextgen rbeckman-nextgen commented May 11, 2020

It appears this is because the default settings for RequestConfig have changed between HttpComponents Client 4.3.3 and 4.5.1. The staleConnectionCheckEnabled variable is now false by default and deprecated.

Imported Comment. Original Details:
Author: narupley
Created: 2016-05-17T13:38:46.000-0700

@rbeckman-nextgen
Copy link
Collaborator Author

@rbeckman-nextgen rbeckman-nextgen commented May 11, 2020

Fixed in revisions 8033/8034. The stale connection setting is now being manually set. For ServerConnection setValidateAfterInactivity is being called since a pooled connection manager is already being used.

Imported Comment. Original Details:
Author: narupley
Created: 2016-05-17T14:40:20.000-0700

@rbeckman-nextgen
Copy link
Collaborator Author

@rbeckman-nextgen rbeckman-nextgen commented May 11, 2020

OS(s) and JRE version:
local OSX Yosemite 10.10 with Java 8 Update 51
Ubuntu 64bits 14.04 , Java(TM) SE Runtime Environment (build 1.8.0_66-b17)

Version(s)/Build(s) to reproduce failure: mirthconnect-3.4.0.8000.b1959-windows-x64
Version(s)/Build(s) to verify fixes: mirthconnect-3.4.1.8036.b129-unix

How Tested:

  • Create HTTP Listener Channel (HTTP Listener/Channel Writer)
  • Create HTTP Sender Channel to above listener channel (Channel Reader/HTTP Sender)
  • Deploy both channel
  • Send message to Sender Channel
  • Verify message sent successfully
  • Stop Listener Channel, wait one minute and restart it again
  • Send another message to Sender
  • Verify message sent successfully

Verified Fixed:
Before fixes, first message sent successfully but second message failed with HTTP Sender Error as in Description
With FIXED, both messages sent successfully

Additional Info:
Issue only found on MacOSx & Ubuntu (but not Windows)

Imported Comment. Original Details:
Author: minht
Created: 2016-05-25T11:29:21.000-0700

@rbeckman-nextgen
Copy link
Collaborator Author

@rbeckman-nextgen rbeckman-nextgen commented May 11, 2020

This ticket has been closed but I think what we should clarify is that this exception can be valid at times. The reason this was filed as a Mirth Connect bug is because the stale connection check was not being done. The connection would be stale but we would still attempt sending data which would result in the server not sending a response since the socket was probably invalidated.

The stale check does not completely avoid this exception though. There is still a chance that a server might not send a response and invalidate a socket(for reasons not related to Mirth Connect).

One case that I would like to focus on is a race condition between the client/server communication. Lets say a client sends a message every 30 seconds and the server has a socket timeout of 30 seconds. It is easy to imagine a scenario where this could be problematic. If the client does a stale check and the server invalidated the socket right after, then what is the result?

In this first screenshot we see a case where a server invalidated the connection right before the client does the stale check. Since the client got a [FIN,ACK] from the server before doing the stale check we can correctly fetch a new connection.
!serverClosesConnectionRightBefore.png!

If you turned on debug logging for apache libraries you would see the following:
DEBUG 2016-09-02 21:19:47,017 [HTTP Sender] org.apache.http.impl.execchain.MainClientExec: Stale connection check DEBUG 2016-09-02 21:19:47,017 [HTTP Sender] org.apache.http.wire: http-outgoing-1444 << "end of stream" DEBUG 2016-09-02 21:19:47,017 [HTTP Sender] org.apache.http.impl.execchain.MainClientExec: Stale connection detected

In this screenshot we actually see the race condition where the stale check happens right before the server invalidates the connection. So the client sends the application data over the same socket and shortly after the server still closes the connection. It doesn't send a response because it was already in the middle of invalidating the connection. Technically the server still got the data.
!serverClosesConnectionAtSameTime.png!

DEBUG 2016-09-02 21:14:06,018 [HTTP Sender] org.apache.http.impl.execchain.MainClientExec: Stale connection check DEBUG 2016-09-02 21:14:06,019 [HTTP Sender] org.apache.http.wire: http-outgoing-1441 << "[read] I/O error: Read timed out" DEBUG 2016-09-02 21:14:06,019 [HTTP Sender] org.apache.http.impl.conn.DefaultManagedHttpClientConnection: http-outgoing-1441: set socket timeout to 30000

I guess there could be cases that make this issue more common but this should demonstrate that it is not a mirth connect issue but rather a race condition at the tcp level. Setting a retry count on a destination would always work, or connections could just always be closed.

Imported Comment. Original Details:
Author: eduardoa
Created: 2016-09-02T18:30:51.000-0700

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Linked pull requests

Successfully merging a pull request may close this issue.

None yet
1 participant
You can’t perform that action at this time.